Set app log level to logging.DEBUG instead of logging.INFO

[claresloggett]

Recently I tried using logging to record debugging information in my callbacks via app.logger (see discussion at https://community.plot.ly/t/logging-debug-messages-suppressed-in-callbacks) and found that some debug messages were being ignored, apparently only when they were logged from callbacks.

It turned out that with the default behaviour (i.e. silence_routes_logging=True), debug messages don't get logged after the server is started as Dash sets self.logger.setLevel(logging.INFO) when app.run_server() is called (see

dash/dash/dash.py

Line 1162 in aac493c

self.logger.setLevel(logging.INFO)

). It's easy to work around, but @ned2 suggested that it might be more sensible for Dash to set its master log level to logging.DEBUG anyway. As an end-user it was not obvious to me why my debug messages were being logged at first and then weren't.

If this would be a sensible change, I'm happy to make a mini-PR.

[ned2]

Just to clarify, there's two loggers that silence_routes_logging=True causes to be modified: the werkzeug logger (that logs route traffic by default) and the one attached to the Dash instance (ie app.logger). The latter of these is the one in question.

I think this line should just be removed (leaving DEBUG as the default), as app.logger doesn't explicitly pertain to routes, and if a user tries to use this logger, any changes to loglevel will be clobbered when run_server is called.

[fohrloop]

I was also surprised when logger.debug() messages did not show up from code that is triggered by a callback. I think that changing logger level from logging.DEBUG to logging.INFO is not something that library code should do without any notification to the user.

My current quickfix was to use

app.logger.setLevel = lambda x: None

between app = dash.Dash() and app.run_server().

Possible fixes

1) Argument to dash.Dash that defines log level

• Add an argument to the dash.Dash(), such as loglevel=logging.INFO that is respected by the dash (and Dash.enable_dev_tools())

2) Change log level only if it is higher than logging.INFO

• The reason for changing the log level in Dash.enable_dev_tools() seems to be that dash itself prints lower level (INFO level) messages to the stdout, and user needs / wants to see them.
• The code could be changed that first it checks if the loglevel is logging.INFO or lower, and if it is, the call to self.logger.setLevel() is skipped. Users that have set the loglevel to logging.DEBUG, have done it for a purpose.

[celia-lm]

Just for reference, the main app.server loglevel is hardcoded in this line: https://github.com/plotly/dash/blob/dev/dash/dash.py#L576
The code linked in the first message of this issue only applies when dev tools are enabled. This is just a clarification because it's a small detail that can cause confusion if we don't read the thread carefully (it happened to me).

Also, here's the updated link to the community forum post the author mentions: https://community.plotly.com/t/logging-debug-messages-suppressed-in-callbacks/17854/4

That said:

• I agree that it makes sense to set loglevel to logging.DEBUG when dev tools are enabled since the most common case where this happens is when developers indicate app.run(debug=True).
• I think it would be useful to add a loglevel argument to the Dash() constructor and/or a logger argument. There's already an add_log_handler argument but it doesn't allow developers to specify the type of handler they want. If the developer wants a custom logger they need to overwrite the default one with app.logger = ... after creating the app object.