Remove sklearn logger default StreamHandler by cdeil · Pull Request #16451 · scikit-learn/scikit-learn

cdeil · 2020-02-16T22:10:41Z

This PR removes the StreamHander which was attached to the sklearn logger on import.

Relevant: #15122 and #15122 (comment) which suggests that this was added for Python 2.
Please note that since Python 3.2, a logging.lastResort default handler was added to the logging standard library, which means that by default your messages will show up for users, even if you don't add this streamhandler.

Note that the standard advice for Python libraries is to not attach handlers:
https://docs.python.org/3/howto/logging.html#configuring-logging-for-a-library

Why is it bad to have the handler?

Because it causes log messages to appear twice, if people add a root logger, which is added by calling e.g. logging.info, like this:

>>> import sklearn
>>> import logging
>>> logging.info("123")
>>> sklearn.logger.info("123")
123
INFO:sklearn:123

Note that the problem of duplicate log messages is an old one, here's a blog post on the issue, and nice tool to figure how how logging works, and which libraries do what:
https://rhodesmill.org/brandon/2012/logging_tree/

Thoughts?

To avoid duplicate log messages

jnothman

It seems I had a review comment lying around for a long time... Maybe we can get this into the upcoming release.

jnothman · 2020-02-16T22:41:44Z

sklearn/__init__.py


 logger = logging.getLogger(__name__)
-logger.addHandler(logging.StreamHandler())
 logger.setLevel(logging.INFO)


Surely we shouldn't be doing this either?

I'm confused what effect this has on the user now. Does setting the level on a logger that has no handler do anything useful?

seems like consensus :)

Should we then remove this one @thomasjpfan ?

Ah yes, we should remove the setLevel as well, updating PR.

thomasjpfan · 2020-04-27T21:03:40Z

Will removing the handler silence the logging output of the dataset module?

jnothman · 2020-04-27T21:25:14Z

It should not on python >= 3.2, due to the last resort logger, but we can check.

thomasjpfan · 2020-04-27T23:31:29Z

Since the logging.lastResort logging is set to output to sys.stderr with level WARNING, the logger used in datasets module will not output anything unless they are at the WARNING level.

Currently, they are all at debug or info.

jnothman · 2020-04-27T23:43:59Z

Hmm so maybe we need docs to supplement this change.

thomasjpfan · 2020-04-28T17:49:18Z

The "quick" way to work through this is to add a verbose option to the fetch_* datasets and change the logging to use print.

It would break backwards compatibility with users that are actively using the logging API and capturing the logs from the fetch_* calls. (I think this is kind of rare.)

adrinjalali · 2020-04-28T17:52:21Z

we really should move the other way around and do more logger rather than going the print way I'd say.

cdeil · 2020-04-28T20:16:51Z

Maybe leaving the INFO level default as in this PR is the best thing to do, to keep the info messages that you want users to see by default. I think removing the handler should be OK, i.e. messages should appear by default on the console without it.

thomasjpfan · 2020-04-28T20:21:25Z

Honestly, I am okay with removing the handler and not having anything print out. We do not have these messages print out when downloading using fetch_openml and I do not think we have any complains.

jnothman · 2020-04-29T12:59:10Z

Yes, let's hide them by default and at most make a what's new note that users should set the logging level if they want these messages to continue

thomasjpfan · 2020-04-29T15:56:19Z

Updated PR with whats new entry stating that a handler should be added to continue to receive messages from the datasets module.

cdeil · 2020-04-29T18:22:04Z

doc/whats_new/v0.23.rst

+- |API| The `StreamHandler` was removed from `sklearn.logger`. To continue to
+  receive logging messages from :mod:`sklearn.datasets`, a handler should
+  be added to `sklearn.logger`. :pr:`16451` by :user:`Christoph Deil <cdeil>`.


I think the statement as-is in the changelog isn't 100% correct. In many cases the last resort handler is in place and will log messages by default to the console. If the user wants to change logging, they can add handlers to the sklear.logger, but e.g. also the root logger.

Maybe not try to explain how logging handlers work via the what's new entry, and to just explain why the handler was removed?

Suggested change

- |API| The `StreamHandler` was removed from `sklearn.logger`. To continue to

receive logging messages from :mod:`sklearn.datasets`, a handler should

be added to `sklearn.logger`. :pr:`16451` by :user:`Christoph Deil <cdeil>`.

- |API| The `StreamHandler` was removed from `sklearn.logger` to avoid

double logging of messages in common cases where a hander is attached

to the root logger, and to follow the Python logging documentation

recommendation for libraries to leave the log message handling to

users and application code. :pr:`16451` by :user:`Christoph Deil <cdeil>`.

I think the statement as-is in the changelog isn't 100% correct. In many cases the last resort handler is in place and will log messages by default to the console.

The last resort handler will log warnings to stderr. The datasets module logs with info and debug levels, and nothing is shown on the console.

Although, I am okay with updating the whats new to your suggestion.

For example:

from sklearn.datasets import fetch_kddcup99 fetch_kddcup99(data_home="data")

will print Downloading https://ndownloader.figshare.com/files/5976042 on master, and nothing with this PR.

I see. So here the sklearn.datasets._kddcup99 logger is created, it has the default level of warning and thus the info message isn't shown.

You could add a logger.setLevel(logging.INFO) there if you want it to appear by default for users.

My understanding is that messing with handlers in libraries is bad (causes confusion and double log messages for users), but messing with log levels is OK in libraries, to get the default behaviour you want.

Another option could be to use the sklearn.logger there to emit the message, but then I think you have to be very careful to avoid circular imports, probably is tricky.

The lastresort handler will still filter everything out.

The only want to get the logging messages to appear is to change the logger to logger.warning.

Anyways, I am okay with removing the messages so we can be a better citizen of using logging.

Hm that seems fine as info and debug seem to be the correct logging levels. We could set the level to 'warning' if we think that downloading the data is unexpect, but 'info' seems right and so it shouldn't be printed by default.

* Remove sklearn logger default StreamHandler To avoid duplicate log messages * DOC Adds whats_new * CLN Address comments * MNT Remove setLevel Co-authored-by: Thomas J Fan <thomasjpfan@gmail.com>

Remove sklearn logger default StreamHandler

555e6fd

To avoid duplicate log messages

cmarmo added the Waiting for Reviewer label Mar 10, 2020

cdeil mentioned this pull request Apr 12, 2020

Remove logging.root basicConfig on pystan import stan-dev/pystan2#685

Closed

jnothman reviewed Apr 27, 2020

View reviewed changes

jnothman added this to the 0.23 milestone Apr 27, 2020

jnothman added Bug and removed Waiting for Reviewer labels Apr 27, 2020

jnothman removed this from the 0.23 milestone Apr 27, 2020

thomasjpfan added 2 commits April 29, 2020 11:42

Merge remote-tracking branch 'upstream/master' into pr/16451

46d8ebb

DOC Adds whats_new

dda7baa

cdeil commented Apr 29, 2020

View reviewed changes

CLN Address comments

df2db8e

adrinjalali mentioned this pull request May 4, 2020

Add more PRs to 0.23.X #17120

Merged

MNT Remove setLevel

ff2ee13

thomasjpfan approved these changes May 4, 2020

View reviewed changes

adrinjalali approved these changes May 4, 2020

View reviewed changes

adrinjalali merged commit a0c76ce into scikit-learn:master May 4, 2020

thomasjpfan mentioned this pull request May 4, 2020

Please don't configure logging in the top-level __init__.py #15122

Closed

-- |API| The `StreamHandler` was removed from `sklearn.logger`. To continue to
-  receive logging messages from :mod:`sklearn.datasets`, a handler should
-  be added to `sklearn.logger`. :pr:`16451` by :user:`Christoph Deil <cdeil>`.
+- |API| The `StreamHandler` was removed from `sklearn.logger` to avoid
+  double logging of messages in common cases where a hander is attached
+  to the root logger, and to follow the Python logging documentation
+  recommendation for libraries to leave the log message handling to
+  users and application code. :pr:`16451` by :user:`Christoph Deil <cdeil>`.

Uh oh!

Conversation

cdeil commented Feb 16, 2020

Uh oh!

jnothman left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

thomasjpfan commented Apr 27, 2020

Uh oh!

jnothman commented Apr 27, 2020 via email

Uh oh!

thomasjpfan commented Apr 27, 2020

Uh oh!

jnothman commented Apr 27, 2020 via email

Uh oh!

thomasjpfan commented Apr 28, 2020

Uh oh!

adrinjalali commented Apr 28, 2020

Uh oh!

cdeil commented Apr 28, 2020

Uh oh!

thomasjpfan commented Apr 28, 2020

Uh oh!

jnothman commented Apr 29, 2020 via email

Uh oh!

thomasjpfan commented Apr 29, 2020

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

6 participants