Duplicate log entries and locked log files in Spyder IDE

Question

What I want: My python script runs, output logging messages to both the console and to a file.

Once the python script finishes running, I want to be able to delete/edit the logging file. I am using Spyder IDE on Windows7.

Example code:

import logging

logging.basicConfig(level=logging.INFO)
logger = logging.getLogger(__name__)
logger.setLevel(logging.INFO)

hdlr = logging.FileHandler("/Users/mds/Dropbox/_python/logger-debug.txt")
logger.addHandler(hdlr) 

logger.error("Am I duplicating error entries?")

hdlr.close()

Problems I'm having:

1. After the script finishes running, there is still a lock on the file

2. Each time I run the script the log file grows many duplicate entries.

first time I run the script:

console:

runfile('C:/Users/mds/Dropbox/_python/logger-debugger.py', wdir='C:/Users/mds/Dropbox/_python')
ERROR:__main__:Am I duplicating error entries?

logger-debug.txt:

Am I duplicating error entries?

Second time I run the script: console:

runfile('C:/Users/mds/Dropbox/_python/logger-debugger.py', wdir='C:/Users/mds/Dropbox/_python')
ERROR:__main__:Am I duplicating error entries?

logger-debug.txt

Am I duplicating error entries?
Am I duplicating error entries?
Am I duplicating error entries?

third time I run the script:

console:

runfile('C:/Users/mds/Dropbox/_python/logger-debugger.py', wdir='C:/Users/mds/Dropbox/_python')
ERROR:__main__:Am I duplicating error entries?

logger-debug.txt

Am I duplicating error entries?
Am I duplicating error entries?
Am I duplicating error entries?
Am I duplicating error entries?
Am I duplicating error entries?
Am I duplicating error entries?

Answer 1

apparently merely closing the handler is not enough. It also needs to be removed from the logger instance.

So now the final correct example is:

import logging

logging.basicConfig(level=logging.INFO)
logger = logging.getLogger(__name__)
logger.setLevel(logging.INFO)

"""remember to close this handler at finish!!!"""
hdlr = logging.FileHandler("/Users/mds/Dropbox/_python/logger-debug.txt")
logger.addHandler(hdlr) 


logger.error("Am I duplicating error entries?")

hdlr.close()
logger.removeHandler(hdlr)

Notice the logger.removeHandler(hdlr) in the new version.

So this cured the problem of locked files. It also cured the problem of multiple runs of the script writing the same log messages several times. Now it's apparent that was happening because there were multiple filehandlers still linked to that logger instance (main), so many handlers simultaneously wrote the same error message. This means I do not have to use overwrite filemode, I can use append filemode too.

I saw an old Stack Overflow message that had this bit of code for deleting all handlers.

handlers = logger.handlers[:]
for handler in handlers:
    handler.close()
    logger.removeHandler(handler)

Answer 2

Spyder IDE uses persistent instances of Python that you may run scripts in and interact with. Each time you run the script, the same instance is used - No objects are cleared.

The log duplication is caused because you're effectively adding multiple handlers to the same logger.

The lock will be present until you close and remove all handlers, or you kill the Python instance/"tab".

Answer 3

As Alastair says, by default spyder do not clean all variables when re-running a script, so that handlers will be added each time. To avoid this, for your case, you can simply check if the handlers list is empty before adding one:

if len(logger.handlers) == 0 :
   logger.addHandler(hdlr) 

Answer 4

For 2 you can call the Filehandler with mode='w' instead of althea default append mode.