[BUG] Logging configuration when running bokeh server

[lunarspectrum]

In Bokeh 1.1.0, when a bokeh application is run on a bokeh server, configuration of the root logger inside the user application via logging.basicConfig or bokeh.utils.logconfig.basicConfig is ignored. This is because basicConfig has already been called when the bokeh server is started and has already assigned a handler to the root logger. The logging.basicConfig function does nothing when a handler is already assigned, which is expected behavior. Documentation on the bokeh server page could help a user to know that to modify the root logger behavior within a program, the root logger handlers must be accessed directly.

[bryevdv]

@lunarspectrum Python logging is frankly confusing to me, and not an area of expertise for me. Are there changes we could make that would be better for users wanting to change logging settings? Perhaps a flag could override the default automatic invocation of basicConfig? We would love to consider a PR from you for any improvements (I'm asking specifically because I think you could make a better PR than I could)

[lunarspectrum]

I'll take a swing at it after the weekend. I agree, python logging is deeply confusing!

[bryevdv]

@lunarspectrum did you still intend to submit any PR around this?

[lunarspectrum]

Oh dear...it has been a while, hasn't it? I still intend to...

[p-himik]

Since I've just spent half a day trying to debug application logging configuration being hijacked by some other libraries, I'd like to add my five cents.

Situations where you need to call basicConfig in application code:

• You implement __main__
• You don't implement __main__ but use some wrapper that doesn't have its own logging configuration.

Situations where you need to call basicConfig in library code:

• Never, unless it's some library/module created specifically for that purpose that follows the "opt-in" principle (i.e. doesn't configure any logging unless you ask it to).

Situations where you need to fiddle with loggers that come from other modules (Dask distributed, I'm looking at you):

• NEVER!

What it means for Bokeh: if Bokeh is used via its bokeh executable, basicConfig should be called by Bokeh; if Bokeh is embedded into some other code, basicConfig must not be called.

[bryevdv]

if Bokeh is embedded into some other code, basicConfig must not be called.

I'm happy to entertain any proposals for changes or updates to Bokeh logging code that satisfy one hard, fast, absolute requirement:

• Deprecation warnings MUST be forced to be visible by default.

That is literally all I care about. I regard it as frankly irresponsible that the default Python state for deprecation warnings is that they not be visible. This just means that most users never ever see them at all, rendering them utterly useless in practice. And more importantly, it means an increased support burden on me personally, that I am not willing to tolerate.

[p-himik]

@bryevdv A good requirement, but it has nothing to do with logging. That is, unless a user replaces the default Python warnings handling. But in that case, all the best are off anyway.
So all should be good, no matter what logging solution will be implemented within Bokeh.

[bryevdv]

@p-himik AFAIK all the current bokeh logging code is in place specifically to service that goal. But I didn't write it, and its not an area of expertise for me, so I might just be wrong. I would be very happy to delete all our logging code if it's proved not actually necessary or useful.Upcoming 2.0 would be a great chance to make breaking changes. But this is a task someone else will have to drive.

[bryevdv]

The relevant files (AFAIK) are

https://github.com/bokeh/bokeh/blob/master/bokeh/__init__.py
https://github.com/bokeh/bokeh/blob/master/bokeh/util/logconfig.py

[p-himik]

@bryevdv Only this code is relevant to the warnings: https://github.com/bokeh/bokeh/blob/master/bokeh/__init__.py#L84-L101. Although, I'm not that sure about the custom implementation of formatwarning - I'd leave it for the application level as well. Overriding built-in methods at a library level is bad.

Default Python implementation (which is being used here, unless a user has already overridden it before that code is executed) writes directly to sys.stderr. Logging configuration has nothing to do with it.

The optimal solution IMO would be to just use logger = logging.getLogger(__name__) where logging is necessary, and then set the logger up in the entry point used by the bokeh executable. That's it. Anything complicated and custom goes there, it doesn't belong in library code.

[p-himik]

BTW a nice implementation reference is the Tornado's one. It customizes message format, date format, colors, rotation, and it ties it all to its CLI options. The only issue I have with it is that if you want to use Tornado's options module, you will have the INFO logging level set as the default, plus some logging setup (but it's done only if you haven't configured any handlers yourself).

[lunarspectrum]

@p-himik and @bryevdv , the bug I submitted is simpler than all of this (I think). When you run bokeh serve, the basicConfig command gets called here:
https://github.com/bokeh/bokeh/blob/master/bokeh/command/subcommands/serve.py#L553
which overrides any call of basicConfig that a user may have in their app. I still think this is essentially a documentation bug, that a user needs to know to either use the CLI option --log-format when calling bokeh serve or they need to access the root logger configuration directly.

The best code-fix I've thought of is to add a keyword option to bokeh's implementation of basicConfig that strips all of the handlers that have been configured, rather than only stripping a single handler, as is done now:
https://github.com/bokeh/bokeh/blob/master/bokeh/util/logconfig.py#L62
(Actually, I haven't quite figured out why it's doing what it is on that line...)
If all the handlers have been stripped from the root logger, then the subsequent call to the basicConfig from the logging module on line 65 will actually do something.

[p-himik]

@lunarspectrum The bug is simpler only on the surface. A proper solution should not require fiddling with already configured handlers.