Logging in Spyder python3.9 causes log printing to increment on each run

Viewed 23

I am trying to setup a python file to log its activity to the console and its own log when called by a main file. When I test this by running my file I am seeing an odd result. When I open Spyder for the first time and run the file I will get one line printed to my log/console, but when I run again there are two of the exact same lines printed. This increments by 1 each time I run, but when I close Spyder and launch it again I start over at one line printed. But when I do this setup in IDLE there is no issue. My goal is to have a logger for this file as well as my main.py file and print both of their information to the console when main is run.

import logging
import sys  

logger=logging.getLogger(LOG_FILENAME)
logger.propagate = False
logger.setLevel(logging.DEBUG)

fh = logging.FileHandler(f'{LOG_FILENAME}.log')
fh.setLevel(logging.DEBUG)

ch = logging.StreamHandler()
ch.setLevel(logging.DEBUG)

formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
fh.setFormatter(formatter)
ch.setFormatter(formatter)

logger.addHandler(fh)
logger.addHandler(ch)


# function definitions needed by main

if __name__ == "__main__":
    calculation_results = 'AAAA'
    logger.debug('{}:{}'.format('Calculation Results', calculation_results) )

First Run Outputs:
2022-09-20 17:42:05,058 - calculation_test - DEBUG - Calculation Results:AAAA

Second Run Outputs:
2022-09-20 17:43:45,217 - calculation_test - DEBUG - Calculation Results:AAAA
2022-09-20 17:43:45,217 - calculation_test - DEBUG - Calculation Results:AAAA

Third Run Outputs:
2022-09-20 17:44:01,616 - calculation_test - DEBUG - Calculation Results:AAAA
2022-09-20 17:44:01,616 - calculation_test - DEBUG - Calculation Results:AAAA
2022-09-20 17:44:01,616 - calculation_test - DEBUG - Calculation Results:AAAA

And so on...

Adding fh.close() and ch.close() at the end of the file did not work. When I try to use the root logger logging.basicConfig() instead of my code above the issue goes away, but as far as I understand this means that I will not be able to configure main to have a separate log file.

I am unsure if my code is bad or if Spyder itself has an issue. Any help is appreciated.

UPDATE:
It seems that the issue is that since Spyder simulatenously is running an interactive session and the kernel is not restarted between runs that every time I ran the file the commands logger.addHandler(ch) and logger.addHandler(fh) were adding to logger.handlers. I added the code:

    for handler in logger.handlers:
        logger.removeHandler(handler)

at the very end of the file which now works fine. Is this the proper way to deal with this issue?

0 Answers
Related