Duplicate and quadruple log messages

Question

I'm trying to write a log file, and, for current debug, write log to console, too. To my surprise, I have a strange output both in console and file

Here's the code:

#in a method in a subclass of ScreenListener
def updateVisible(self):
    if all([section['isOK'] for section in self.status_dict.values()]):
        self.config(state = "normal", text = 'Start', relief = RAISED, command=self.monitorROI)                
    else:
        self.config(state = "disabled", text = 'Stop', relief = SUNKEN)

def stopMonitoring(self):
    logger.info('Monitoring stopped')
    self.config(state="normal", text='Start', relief=RAISED, command=self.monitorROI)
    if self.halarm is not None:
        self.after_cancel(self.halarm)
        self.halarm = None 

def monitorROI(self):
    logger.info('Monitoring started')
    self.config(state="normal", text='Started', relief=SUNKEN, command=self.stopMonitoring)
    self.halarm = self.after(100, self.getColorDiff)

def main():    
    tk_root = Tk()
    listener_gui = ScreenListener(tk_root)
    tk_root.mainloop()

if __name__ == '__main__':
    logger = logging.getLogger(__name__)
    logger.setLevel(logging.INFO)
    curr_dir = os.path.dirname(os.path.realpath(__file__))
    log_fpath = "{}/screen_listener.log".format(curr_dir)
    lfh = logging.FileHandler(log_fpath)
    lfh.setLevel(logging.INFO)
    ch = logging.StreamHandler()
    ch.setLevel(logging.INFO)
    formatter = logging.Formatter(fmt='%(asctime)s.%(msecs)03d : %(message)s',datefmt='%d.%m.%Y,%H:%M:%S')
    lfh.setFormatter(formatter)
    ch.setFormatter(formatter)
    logger.addHandler(ch)
    logger.addHandler(lfh)    
    main()

Here's the output

Console (duplicates)

05.06.2019,03:47:09.185 : 
05.06.2019,03:47:09.185 : Monitoring started
05.06.2019,03:47:24.670 : 
05.06.2019,03:47:24.670 : Sending command

Log file (quads)

05.06.2019,03:47:09.185 : 
05.06.2019,03:47:09.185 : 
05.06.2019,03:47:09.185 : 
05.06.2019,03:47:09.185 : Monitoring started
05.06.2019,03:47:24.670 : 
05.06.2019,03:47:24.670 : 
05.06.2019,03:47:24.670 : 
05.06.2019,03:47:24.670 : Sending command

Could you please suggest what is the reason?

I think that’s because you’re propagating to the root logger? You might want to check how LogEntries propagate up the logger tree ([here](https://docs.python.org/3/howto/logging.html#logging-flow)). — Jens, Jun 05 '19 at 01:06

score 0 · Accepted Answer · answered Jun 05 '19 at 12:35

Checking the number of already added handlers did the trick

if not len(logger.handlers):
     logger.addHandler(ch)
     logger.addHandler(lfh)

Alternatively, using logging.config.dictConfig (for details please see this answer) will help, too.

However, I don't get how does the code where the handlers are added run more than once.

Duplicate and quadruple log messages

1 Answers1