Tensorflow causes logging messages to double

Question

So I was playing around with Google's Tensorflow library they published yesterday and encountered an annoying bug that keeps biting me.

What I did was setup the python logging functions as I usually do, and the result was that, if I import the tensorflow library, all messages in the console started doubling. Interestingly, this does not happen if you just use the logging.warn/info/..() function.

An example of a code that does not double the messages:

import tensorflow as tf
import logging

logging.warn('test')

An example of a code that does double all messages:

import tensorflow as tf
import logging

logger = logging.getLogger('TEST')
ch = logging.StreamHandler()
logger.addHandler(ch)

logger.warn('test')

Now, I'm a simple man. I like the functionality of logging, so I use it. The setup with the logger object and the adding of a StreamHandler is something I picked up looking at how other people did this, but it looks like it fits with how the thing was meant to be used. However, I do not have in-depth knowledge of the logging library, as it always just kind of worked.

So, any help explaining why the doubling of the messages occurs will be most helpful.

I am using Ubuntu 14.04.3 LTS with Python 2.7.6, but the error happens in all Python 2.7 versions I tried.

Nari

I'm having a hard time replicating this on ubuntu 14.04 also with python 2.7.6: python testlog.py WARNING:root:test Can you provide a bit more detail about how you installed tf? – Hispaniola

Ah! There's a typo in your sample code. The last line should be logger.warn('test') instead of logging.warn. Now I've replicated it. And the answer is a bit more clear - hang on. – Hispaniola

Answer 1

I get this output:

test
WARNING:TEST:test

Tensorflow is also using the logging framework and has set up its own handlers, so when you log, by default, it propagates up to the parent logging handlers inside tensorflow. You can change this behavior by setting:

logger.propagate = False

See also duplicate output in simple python logging configuration

Followup: This was an unintended side-effect of the way tensorflow was using the logging package. I've changed it at HEAD to scope its internal loggers under the name "tensorflow" to avoid this pollution. Should be in the github head within a day or so. In the meantime, the logger.propagate solution will work and won't break once that fix is in, so you should be safe to go. Thanks again for spotting this!

Followup-Followup: Starting with TensorFlow 1.14 exposes the logger directly:

import tensorflow as tf

logger = tf.get_logger()

Hispaniola

(I'm going to check whether this is actually intended or a bug - I've never encountered it or thought too much about it.) – Hispaniola

Tensorflow isn't using the logging package in the standard way of doing getLogger(name), which is why you're seeing that namespace collision. I'll send a patch for this and see if we can get it happier. Thanks for asking about this! – Hispaniola

Something like the earlier doubling effect can still happen in REPLs. Not a problem, but could be surprising. I wrote up a little post on logging and describe that phenomenon more there. – Rhinal

@Hispaniola shouldn't this be fixed? Expierencing the issue again in TensorFlow 2.X – Gammy

Answer 2

logger.propagate = False solved my problem. I think this is a bug of tensorflow

Synopsis

What is the difference between your answer and the accepted answer? – Teammate