Allennlp: Logging is being duplicated.

[mrdrozdov]

Describe the bug
It looks like the allennlp logger is duplicating my code's logger.

To Reproduce
Steps to reproduce the behavior

1. from allennlp.modules.elmo import Elmo
2. Create logger.

import logging
logger = logging.getLogger('asdf')
logger.setLevel(logging.INFO)
# Also log to console.
ch = logging.StreamHandler()
ch.setLevel(logging.INFO)
# create formatter and add it to the handlers
formatter = logging.Formatter('notallennlp - %(message)s')
ch.setFormatter(formatter)
# add the handlers to the logger
logger.addHandler(ch)

1. Try to log something:

logger.info('test')

1. See error

notallennlp - test
01/28/2019 11:29:44 - INFO - asdf -   test

Expected behavior
The allennlp logger should not be copying my logger. In other words, only the first line should be printed.

System (please complete the following information):

• OS: OSX
• Python version: 3.6.7
• AllenNLP version: 0.8.1

Additional context
n/a

[mrdrozdov]

Btw, calling logger.parent.handlers.pop() fixes this problem, but I'm not sure why. Does allennlp modify the global logger?

[mrdrozdov]

Some more info:

In [3]: logger.parent.handlers
Out[3]: []

In [4]: logger.parent
Out[4]: <RootLogger root (WARNING)>

In [5]: from allennlp.modules.elmo import Elmo

In [6]: logger.parent
Out[6]: <RootLogger root (INFO)>

In [7]: logger.parent.handlers
Out[7]: [<StreamHandler <stderr> (NOTSET)>]

[schmmd]

If you're including AllenNLP as a library--it shouldn't modify your logging. If you are using theallennlp command, it's configured here: https://github.com/allenai/allennlp/blob/master/allennlp/run.py#L12

[mrdrozdov]

As I noted, I am using AllenNLP as a library by:

from allennlp.modules.elmo import Elmo

[schmmd]

Weird--and yes--I'm able to reproduce this in our Docker image for v0.8.1. I might be able to dig into this at some point, but logging issues tend to be pretty nuanced to figure out. Contributions are very welcome!

[mrdrozdov]

Nice! I tried to figure this out, but no luck. In my code I use the workaround — removing handlers from the global logger before running my code.

[mrdrozdov]

So not sure the source of the bug, but this is bothering me. I created a script to try many different imports and find culpable ones. Here it is: https://gist.github.com/mrdrozdov/e6bb6137e509561c725dc9541b283864

It looks like any import from modules or data cause the described behavior.

[matt-gardner]

Could it be something to do with this? https://github.com/allenai/allennlp/blob/master/allennlp/data/dataset_readers/multiprocess_dataset_reader.py#L6

If you remove that class, do you still see the issue?

[mrdrozdov]

Not quite. I had to remove any references to pytorch_pretrained_bert then the extra logging went away.

Somehow, could it be caused by this? https://github.com/huggingface/pytorch-pretrained-BERT/blob/master/examples/run_classifier.py#L39

EDIT: Thanks for pointing this out though! It gave me the idea to look for more packages containing torch in the title.

[schmmd]

I would hope that couldn't cause it--as it's just an example script. We don't import it directly and hopefully huggingface doesn't import it either.

[thomwolf]

We don't.
Please make sure you have a recent version of pytorch-pretrained-bert (0.4.0). There used to be an issue with logging in the early versions.

import pytorch_pretrained_bert
pytorch_pretrained_bert.__version__

[mrdrozdov]

Nice. So allennlp 0.8.1 is latest released version I believe, and it links to pytorch-pretrained-bert (0.3.0), although 0.8.2 is linked to (0.4.0). So fixed in next release?

0.8.1
https://github.com/allenai/allennlp/blob/87f977a5fd58568d44d68499521ab0d71f8a0012/requirements.txt#L73

vs. master (0.8.2)
https://github.com/allenai/allennlp/blob/master/requirements.txt#L70

[schmmd]

Great--thanks for the troubleshooting @mrdrozdov. I'll update our dependency version.

[schmmd]

Ah, and I misunderstood. We moved master to 0.4.0 already (in 083f49ea0) so we just need another relase.

[mrdrozdov]

Closing since this is in master.