python.logging: Why does my non-basicConfig setting not work?

Question

I want to log to a single log file from main and all sub modules.

The log messages send from a main file, where I define the logger, work as expected. But the ones send from a call to an imported function are missing.

It is working if I use logging.basicConfig as in Example 1 below. But the second example which allows for more custom settings does not work.

Any ideas why?

# in the submodule I have this code
import logging
logger = logging.getLogger(__name__)

EXAMPLE 1 - Working

Here I create two handlers and just pass them to basicConfig:

# definition of root looger in main module

formatter = logging.Formatter(fmt="%(asctime)s %(name)s.%(levelname)s: %(message)s", datefmt="%Y.%m.%d %H:%M:%S")   

handler = logging.FileHandler('logger.log')
handler.setFormatter(formatter)
handler.setLevel(logging.DEBUG)

handler2 = logging.StreamHandler(stream=None)
handler2.setFormatter(formatter)
handler2.setLevel(logging.DEBUG)

logging.basicConfig(handlers=[handler, handler2], level=logging.DEBUG)
logger = logging.getLogger(__name__)

EXAMPLE 2 - Not working

Here I create two handlers and addHandler() them to the root logger:

# definition of root looger in main module

logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)

handler = logging.FileHandler('logger.log')
handler.setFormatter(formatter)
handler.setLevel(logging.DEBUG)
#handler.setLevel(logging.ERROR)
logger.addHandler(handler)

handler = logging.StreamHandler(stream=None)
handler.setFormatter(formatter)
handler.setLevel(logging.DEBUG)
logger.addHandler(handler)

Hak

Example 2 does work for me (if I copy your formatter = logging.Formatter(...) line from the first). Is there more to this project that could be affecting things? – Scruple

You can really see a module1.DEBUG: test in the log file and the console? I am not sure what else might cause the problem. I boiled this down from my project to a minimum working example that still shows the behaviour. My first thought was that I am doing something wrong with logging's singleton thing. – Hak

What are you calling to generate log entries? logging.warn() or logger.warn(), you should use logger (where warn() is just a placeholder for any of the logging methods (info, debug, etc). – Scruple

Yes, I am using logger.debug('test'). Just tested logging.debug('test'), also does not show up. – Hak

Can you show your root logger configuration? – Scruple

Sure, how? :) Is that a dict? – Hak

Sorry, I was just going from your comment # definition of root looger in main module, I thought you set up the root logger in a different file. – Scruple

Answer 1

You need to configure the (one and only) root logger in the main module of your software. This is done by calling

logger = logging.getLogger() #without arguments

instead of

logger = logging.getLogger(__name__)

(Python doc on logging)

The second example creates a separate, child logger with the name of your script.

If there are no handlers defined in the submodules, the log message is being passed down to the root logger to handle it.

A related question can be found here: Python Logging - How to inherit root logger level & handler

Scruple

Yes, I see 2018.07.01 22:02:04 __main__.DEBUG: got here (Python 3.4) – Hak

Ok great (it should also appear in the .log file). So now you've got to figure out what you're doing differently in your code - because you know this works. – Scruple

The problem is not the messages I am sending from my main module. They are always there. But I am not getting the ones from modules I import. Could you create a module with some function and see if you can log messages if you call the function from the main module? – Hak

Sorry, should have been clearer on this, updated question. – Hak

Got it. In your first example you're configuring the root logger, in the second you're creating a separate, child logger with the name of your script. If you want to configure the root logger directly, use logger = logging.getLogger() instead of logger = logging.getLogger(__name__). – Scruple

Yep, now it works. But the %(name)s in the log now states root for the submodule. Is this the same with you? – Hak

It might be a duplicate of this: #47423189, will try – Hak

The comment about the root looger is the correct answer. Will you edit your answer or should I do it? – Hak

@Joe, go for it :) (and make sure to mark it as answer, there's a badge for that, I think) – Scruple

Done, the edit should be visible soon. Ok like that? – Hak

@Joe, I thought you meant add your own answer to the question and self check that, but I can "approve" your edit if you want. – Scruple

Sure. Your hint, your rep :) – Hak

@Joe, all set, thanks (and happy to help, if just a bit) – Scruple