dash icon indicating copy to clipboard operation
dash copied to clipboard

Dash object adds handler to logger creating extra handler

Open DBCerigo opened this issue 5 years ago • 9 comments

Hi,

Just ran into this issue that stems from the two conventions of

logger = logging.getLogger(__name__)
app = dash.Dash(__name__)

and the line https://github.com/plotly/dash/blob/3a1a1c6dbc6cd96040148f927af808c1a60e22f8/dash/dash.py#L217

This results in an extra handler being added to the __name__ logger which is presumably unwanted by the user.

I think the convention is to add at most add a logging.NullHandler() handler to logging library/packages. From Configuring Logging for a Library section (though it's Python2 fyi), it states:

Note: It is strongly advised that you do not add any handlers other than NullHandler to your library’s loggers. This is because the configuration of handlers is the prerogative of the application developer who uses your library. The application developer knows their target audience and what handlers are most appropriate for their application: if you add handlers ‘under the hood’, you might well interfere with their ability to carry out unit tests and deliver logs which suit their requirements.

When I have a moment I would be happy to try and open a small PR rectifying it if maintainers decide they would want to avoid adding logging handlers in Dash.

Nice one :)

DBCerigo avatar May 30 '19 16:05 DBCerigo

I just ran into this bug, which caused my package level loggers to output everything in duplicate. I spent quite a while debugging it, since thought it was caused by Flask.

I strongly agree with the idea of not adding logging handlers. What happened in my case was that my package already had a logger by __name__ and then Dash forcibly added a StreamHandler to it.

jjnurminen avatar Sep 11 '19 13:09 jjnurminen

A possible workaround is the following:

log = logging.getLogger(__name__)
dashapp1 = dash.Dash(.... )
# remove last handler. The one added by dash
log.handlers.pop()

RiccardoNizzolo avatar Nov 07 '19 17:11 RiccardoNizzolo

@RiccardoNizzolo yep that's how I work around it currently also,

DBCerigo avatar Nov 07 '19 18:11 DBCerigo

Working around it is easy once you figure out what's going on. But at least for me, that took quite a while. Please don't force logging handlers on us :)

jjnurminen avatar Nov 07 '19 18:11 jjnurminen

I'm annoyed that the team would do that, add a handler in this manner. Similar to @jjnurminen I spent hours and hours trying to nail down the cause. I didn't want to just remove handlers as a workaround until I figured out why I was getting so many messages ("Did I configure logging wrong?").

Don't get me wrong, love Dash for what it makes possible, which is a lot. But let's save other developers from this trouble.

bg-bi avatar Nov 08 '19 19:11 bg-bi

Bump this ticket as I see this ticket now after I created a ticket to JupyterDash https://github.com/plotly/jupyter-dash/issues/61. While I think this issue is less obvious with Dash, it's obvious and annoying with JupyterDash as with Jupyterlab one could repeatedly run notebook cell that creates JuptyerDash object.

iynehz avatar May 18 '21 10:05 iynehz

I just hit this and like others had to spend a while to determine that dash was adding a sysout handler as its not expected that a library makes changes to your logging configuration. It's frustrating as it goes to std out without any formatting.

Should use "logging.NullHandler()" to avoid warnings with a config to turn on if required.

An example of how this is done better is the AWS library where NullHandler is used by default with the ability to add a handler is there if required. https://github.com/boto/boto3/blob/develop/boto3/init.py

lionelport avatar Sep 23 '21 03:09 lionelport

3 years later this is still not fixed... a library/package should not be setting up own handlers - this is responsibility of end-user application. At the very least that should be an opt-in for those who can't be bothered setting up their own handlers.

nirvana-msu avatar Jul 10 '22 00:07 nirvana-msu

Apologies for not providing a maintainer response to this issue before. We're really hardly using this logger. There's one debug log that we can probably just delete. The only one we care about is the one that displays the url we're serving on:

https://github.com/plotly/dash/blob/5baac83c6e2e0222c52c193b6eb74833e184aaf1/dash/dash.py#L1949

That message should definitely be displayed by default, but is there any reason not to just print it? If we did that, I guess we wouldn't want to remove self.logger entirely, or everyone using these workarounds would see their code fail, but we could drop it to an unused NullHandler and remove it if and when we make a new major release.

alexcjohnson avatar Jul 11 '22 16:07 alexcjohnson

I would happily have my application break and have to remove my stupid hacks to mydashapp.logger if y'all would get rid of these handlers. As others have said, libraries shouldn't be setting up handlers.

shea-parkes avatar Jan 18 '23 20:01 shea-parkes

I have tried all above mentioned workarounds. It doesn't work. As soon as I add my custom logger and FileHandler to it, very log starts to be duplicated.

nijat-aliyev avatar Feb 02 '23 09:02 nijat-aliyev