2

Forgive me, still learning how to use the logging module. So, I have two handlers, one to log everything to a file and one specifically to log the message when triggered into Hipchat.

I don't quite understand what it means to have root vs non-root loggers. As it is below, it will write what I want to my log file AND displays both messages into the hipchat room. So I found another stack post that says to create two multiple "non root loggers." So I tried it with logger = logging.getLogger('test1') and hipchat_logger = logging.getLogger('test2') but there's no message in Hipchat (it does write to the log file).

logger = logging.getLogger()    
hipchat_logger = logging.getLogger()

# File handler
file_handler = logging.FileHandler("mylog.log", "a")    
logger.addHandler(file_handler)
logger.setLevel(logging.DEBUG)

# Hipchat handler
hipchat_handler = hiplogging.HipChatHandler(MY_TOKEN, CHATROOM)
hipchat_handler.setLevel(logging.DEBUG)
hipchat_logger.addHandler(hipchat_handler)

# Testing
logger.info("Hi, this is a test. I should not see this in Hipchat")
hipchat_logger.info("Hi, display me in Hipchat")
sdot257
  • 10,046
  • 26
  • 88
  • 122
  • Does this work with only HipChatLogger ? – sarveshseri Feb 04 '15 at 00:45
  • By itself you mean without the `logger` handler, then yes it does. It's only when I have multiple handlers. – sdot257 Feb 04 '15 at 00:47
  • `assert logger is hipchat_logger` → True shows that you are getting the same logger from both (static) calls to `logging.getlogger()`. You need to instantiate another logger with something like https://docs.python.org/2/library/logging.html#logging.getLoggerClass – msw Feb 04 '15 at 01:01
  • 1
    Oh, I just looked at the code, but the text says, that you did all that what we proposed. So maybe try something like `logger=logging.getLogger()` with `hipchat_logger=logging.getLogger('hipchat')`? – zormit Feb 04 '15 at 01:05

2 Answers2

3

Problem is in the first two lines. "Multiple calls to getLogger() with the same name will always return a reference to the same Logger object.", cf. here.

So a solution would be (modified after discussion in comments):

logger = logging.getLogger()    
hipchat_logger = logging.getLogger("hipchat")

EDIT

After more research on this topic: The problem is certainly not the missing root logger. There is a problem with loglevels:

Logging messages which are less severe than lvl will be ignored. When a logger is created, the level is set to NOTSET (which causes all messages to be processed when the logger is the root logger, or delegation to the parent when the logger is a non-root logger). Note that the root logger is created with level WARNING.

So what does happen here?

# implicit root logger with loglevel WARNING

# both child-logger: loglevel NOTSET
logger = logging.getLogger('file')
hipchat_logger = logging.getLogger('hipchat')

# ...create and add file handler...

# change 'file'-loglevel to DEBUG
logger.setLevel(logging.DEBUG)

# ...create hipchat handler...

# change loglevel of the handler(!) to DEBUG.
# 'hipchat'-loglevel is still NOTSET
hipchat_handler.setLevel(logging.DEBUG)

# ...add hipchat handler ...

# logger -> loglevel DEBUG -> INFO gets logged.
logger.info("Hi, this is a test. I should not see this in Hipchat")

# hipchat_logger -> loglevel NOTSET -> delegate to root-logger
# root-logger -> loglevel WARNING -> INFO not logged (being below threshold)
hipchat_logger.info("Hi, display me in Hipchat")

So to solve this issue, either explicitly set the loglevel of root logger to DEBUG (as in the code above). Or simply set the loglevel of the second logger accordingly:

hipchat_logger.setLevel(logging.DEBUG)

A question that might remain is answered elsewhere: What is the point of setlevel in a handler?

Community
  • 1
  • 1
zormit
  • 533
  • 4
  • 16
  • I've tried this, please read the last sentence before the sample code. – sdot257 Feb 04 '15 at 01:10
  • @luckytaxi yep, I realized it, as commented in your question. – zormit Feb 04 '15 at 01:12
  • I got it working. your solution in the comment works :-) If you want to modify your answer I will accept it. I left the `logger` handler empty and passed a name to the `hipchat_logger` handler. – sdot257 Feb 04 '15 at 01:13
  • 1
    ok thats nice. I wonder though, why the "two non root solution" does not work with hipchat. I did a test with two sub-loggers, which work (python 2.7). – zormit Feb 04 '15 at 01:19
  • Wow, thanks for the additional research and explanation. Makes complete sense now. – sdot257 Feb 04 '15 at 15:04
3

One with your code problem is that calling logging.getLogger() multiple times returns the same logger.

# both of these are same logger instances
logger = logging.getLogger()    
hipchat_logger = logging.getLogger()

To get two different instance, give different names to different loggers. Also, with no name parameter, you get the root logger.

root_logger = logging.getLogger()

logger = logging.getLogger("file")
hipchat_logger = logging.getLogger("hipchat")

#now getting the logger with same name will return same logger
this_is_same_as_logger = logging.getLogger("file")
sarveshseri
  • 13,738
  • 28
  • 47