FileHandler not sending output to either location

Question

First time playing around with the logging module. I have two questions really:

All of the examples I have found on creating a FileHandler just use a dummy file name, but I want my log file to have a certain title format.

log = time.strftime('./logs/'+'%H:%M:%S %d %b %Y', time.localtime())+'.log'
logger = logging.getLogger('myproject')
formatter = logging.Formatter('%(asctime)s %(message)s', '%H:%M:%S %d %b %Y')
handler = logging.FileHandler(log)
handler.setFormatter(formatter)
logger.addHandler(handler)
logger.setLevel(logging.DEBUG)

This seems to work at first, in that the log file is created, but when I kill the script and examine it, there is nothing in it. And before you suggest using with open(log) as f:, using f in place of log in handler = logging.FileHandler(log) gives me errors about the file not even being created. What am I doing wrong to not have the log file written to? Is it because I'm trying to be too clever with the filename?

The second question may subsume the first somehow. What I would really like is a way to write to both the console and the log file concurrently, since this script takes a long time and I'd like to gauge progress. I have seen that there are answers on how to do this, such as here, but all of these seem to assume that I want different levels of logging for the two different outputs; I don't. Incidentally, I do realize that if my script didn't dynamically generate the name of the log file, I could do something like python myscript.py | tee log.file to avoid making different handlers.

I feel I am having trouble answering my second question because of the variables involved in the first, but I am foggy right now due to illness and subsequent lack of sleep. If someone could explain to me like a five-year-old how to write to both a console and log file with identical output, I would greatly appreciate it.

Many thanks.

Answer 1

Your code is configuring a logger named 'myproject':

logger = logging.getLogger('myproject')
logger.addHandler(handler)
logger.setLevel(logging.DEBUG)

If you use methods on that logger, everything will work:

logger.info('foo bar')
logging.getLogger('myproject').info('foo bar')

But if you just use the module-level functions, it will not:

logging.info('foo bar')

Why? Because the module-level functions use the default root logger, which is not the one you've configured. See the docs for details on how this works.

Generally, the way you deal with this is either to create a module-level logger object for each module, like this:

logger = logging.getLogger(__name__)

… or a class or instance attribute logger, something like this:

self.logger = logging.getLogger('{}.{}'.format(__name__, cls.__name__))

And then do everything through that logger or self.logger object, not through the module-level functions.

So, why are the module-level functions even there? For convenience in simple programs, mainly. If that sounds appropriate for you, and you want to use them, you can; you just have to configure the root logger instead of a different one. Change the first line to this:

logger = logging.getLogger()

Now when you configure logger, you're also configuring the module-level functions.