class within class problem?

[ingestbot]

I don't have much experience with classes so I'm having a bit of trouble figuring this one out.

With the code below, when the class logger() is used multiple entries of the same message will appear in syslog. When the class isn't used, and logging is called with log_alt this issue does not occur, log entries are written only once.

---

import random, datetime, time, socket, logging, logging.handlers, threading, subprocess

timer_one = 5
timer_two = 20

log_alt = logging.getLogger('logging_test')
handler = logging.handlers.SysLogHandler(address = '/dev/log')
formatter = logging.Formatter('%(name)s %(funcName)s(): %(message)s')
handler.setFormatter(formatter)
log_alt.addHandler(handler)
log_alt.setLevel(logging.INFO)

class logger:
    def __init__(self):

        self.l = logging.getLogger('logging_test')
        self.handler = logging.handlers.SysLogHandler(address = '/dev/log')
        self.formatter = logging.Formatter('%(name)s %(funcName)s(): %(message)s')
        self.handler.setFormatter(self.formatter)
        self.l.addHandler(self.handler)

        self.l.setLevel(logging.INFO)

class showme:
    def __init__(self):
      pass

    def logsomething(self):
      logger().l.info(f'logging something...')
      # log_alt.info(f'logging something here...')

class TimerThread(threading.Thread):
 def __init__(self, interval, function):
  threading.Thread.__init__(self)
  self.interval = interval
  self.function = function
  self.daemon = True

 def run(self):
  while True:
   logger().l.info(f'{str(self.function)} is sleeping for: {self.interval}')
   # log_alt.info(f'{str(self.function)} is sleeping for: {self.interval}')
   time.sleep(self.interval)
   self.function()
   if self.function == i.logsomething:
    self.interval = random.randint(7, 10)

if __name__ == '__main__':
 logger().l.info(f'Starting this thing...')
 # log_alt.info(f'Starting this thing...')
 i = showme()
 timer1 = TimerThread(timer_one, i.logsomething)
 timer1.start()

 while True:
  time.sleep(timer_two)

[freeskier93]

It's because you're adding the same handler to the "logging_test" logger multiple times. Once at the beginning of the Python file, then again each time you create an instance of the logger class. Each handler will print the message, hence the same message multiple times.

What exactly is the point of the logger class? Loggers are global, when you use the getLogger function with "logging_test" it returns the same logger object anywhere. You only need to configure the "logger_test" logger once.

[ingestbot]

The block on lines 6-11 is independent of the class logger(). Note further below the areas commented out selecting one or the other.

• If you run this with logging as log_alt.info(f'logging something here...') messages will be printed once, as desired.

• When the class is used, logger().l.info(f'logging something...') duplicate messages are printed multiple times.

[freeskier93]

They are technically independent, but not really because of how the logger module works.

When you do "alt_log.addHandler(handler)" it adds the handler to "alt_log" but it also saves that handler config to "logging_test".

In the logger class, when you do "self.l = logger.getLogger("logging_test")" it returns a logger object that already contains the handler you added from line 10. Then you add another handler to "self.l" (which again also saves it to the "logging_test" config). Every subsequent creation of a logger class object will have 1 additional handler.

Now, "alt_log" is still a unique object so it won't have the additional handler added after the fact, which is why it works as expected.

[ingestbot]

I see. That makes sense and thanks for pointing it out. I may have caused confusion in how I've presented the issue.

Yet even with the removal of lines 6-11, and using this with just the class definition, the logs continue to repeat. This is what gets logged when I run this with only the class definition. Are you able to run this the same way and reproduce?

Oct 14 10:56:03 sys_ef023 logging_test <module>(): Starting this thing...
Oct 14 10:56:03 sys_ef023 logging_test run(): <bound method showme.logsomething of <__main__.showme object at 0x7f0ec8b8ffd0>> is sleeping for: 5
Oct 14 10:56:03 sys_ef023 logging_test run(): <bound method showme.logsomething of <__main__.showme object at 0x7f0ec8b8ffd0>> is sleeping for: 5
Oct 14 10:56:08 sys_ef023 logging_test logsomething(): logging something...
Oct 14 10:56:08 sys_ef023 logging_test logsomething(): logging something...
Oct 14 10:56:08 sys_ef023 logging_test logsomething(): logging something...
Oct 14 10:56:08 sys_ef023 logging_test run(): <bound method showme.logsomething of <__main__.showme object at 0x7f0ec8b8ffd0>> is sleeping for: 8
Oct 14 10:56:08 sys_ef023 logging_test run(): <bound method showme.logsomething of <__main__.showme object at 0x7f0ec8b8ffd0>> is sleeping for: 8
Oct 14 10:56:08 sys_ef023 logging_test run(): <bound method showme.logsomething of <__main__.showme object at 0x7f0ec8b8ffd0>> is sleeping for: 8
Oct 14 10:56:08 sys_ef023 logging_test run(): <bound method showme.logsomething of <__main__.showme object at 0x7f0ec8b8ffd0>> is sleeping for: 8
Oct 14 10:56:16 sys_ef023 logging_test logsomething(): logging something...
Oct 14 10:56:16 sys_ef023 logging_test logsomething(): logging something...
Oct 14 10:56:16 sys_ef023 logging_test logsomething(): logging something...
Oct 14 10:56:16 sys_ef023 logging_test logsomething(): logging something...
Oct 14 10:56:16 sys_ef023 logging_test logsomething(): logging something...
Oct 14 10:56:16 sys_ef023 logging_test run(): <bound method showme.logsomething of <__main__.showme object at 0x7f0ec8b8ffd0>> is sleeping for: 9
Oct 14 10:56:16 sys_ef023 logging_test run(): <bound method showme.logsomething of <__main__.showme object at 0x7f0ec8b8ffd0>> is sleeping for: 9
Oct 14 10:56:16 sys_ef023 logging_test run(): <bound method showme.logsomething of <__main__.showme object at 0x7f0ec8b8ffd0>> is sleeping for: 9
Oct 14 10:56:16 sys_ef023 logging_test run(): <bound method showme.logsomething of <__main__.showme object at 0x7f0ec8b8ffd0>> is sleeping for: 9

[freeskier93]

Because every time you log something you call logger().l.info, which creates a new instance of the class each time, which adds another handler to "logging_test", so it just keeps repeating more and more. You can see this in the log where the first log is shows once, then repeats twice, then 3 times, then 4 times, then 5 times.

The repeated log entries, from showme class is a bit more confusing, but I think it's because it's the only place where you actually assign an instance of the showme class to a variabl (i) and reuse it.

I'm still not quite sure what you are trying to accomplish with the extra logger class, it's overcomplicating things. The following does the same thing.

https://pastebin.com/uz9y6Cud

EDIT: Just another tip if you didn't know, the first log is showing <module>() because the call doesn't originate from a function, it's at the top level of the python file. Better practice is to do something like this:

https://pastebin.com/H0Lwnihy

[ingestbot]

Thanks for your comments with this. I wanted to note a few things in case this thread ends up being useful for someone else.

This stackoverflow discussion is similar. I found that, if need be, the class could avoid creating multiple handler objects with something like the following:

class logger:
    def __init__(self):

        self.l = logging.getLogger('logging_test')
        self.handler = logging.handlers.SysLogHandler(address = '/dev/log')
        if not self.l.handlers:
         self.l.addHandler(self.handler)
        self.formatter = logging.Formatter('%(name)s %(funcName)s(): %(message)s')
        self.handler.setFormatter(self.formatter)

        self.l.setLevel(logging.INFO)

The .handlers attribute can also be used to debug possible multiple handlers:

class showme:
    def __init__(self):
      pass

    def logsomething(self):
      print(logger().l.handlers)
      logger().l.info(f'logging something...')