Logging - debug messages suppressed in callbacks?

[clare]

Hi all,

I’ve been trying to use the logging module to log from my Dash app. Reading about logging and flask suggested I should use flask’s own logger app.logger, so that my messages and flask’s messages go to the same place. Trying this directly with the app object created by Dash seems to work well.

The only issue is that some of my debug messages are not being logged. I would normally assume I have made a mistake in setting a log level somewhere. But some debug messages are getting through! If I add lines like

app.logger.debug('Test debug')
app.logger.info('Test info')

to the app right after the app = dash.Dash(), both messages are logged. But if I add the exact same lines to a callback, only the info message is logged. I’m stuck in working out the cause. Is it possible this is something to do with how Dash manages callbacks?

I was really hoping to use debug messages to diagnose issues in callbacks. Any help much appreciated!!

I am setting (I think) the relevant log levels and am using app.run(debug=True). Otherwise I think the debug message at the start of the app would not get through either.

Clare

[nedned]

Did you mean app.run or app.run_server? If the latter, this is expected behaviour as supplying run_server debug=True causes Dash to set app.logger to the loglevel logging.INFO

That said, I think it would make more sense if it was being set to logging.DEBUG

[clare]

Sorry yes, I mean app.run_server(). That makes perfect sense as my initial tests (which work) were called during app creation, before run_server. Thanks @nedned !

So the workaround for now is probably for me to set the log level back to DEBUG after calling run_server(). I don’t know any really sensible place to do this. I can do it in my serve_layout() function, which is run every time a new browser session is initialised - that will cause it to be called multiple times, unnecessarily, but less so than putting it in a callback. Is there any more sane place to put initialisation code that needs to go after run_server() has started?

I just had a look at the dash code and it looks like it’s setting the Dash logger to logging.INFO, and the getLogger('werkzeug') logger (which I think is the Flask logger?) to logging.ERROR. I can’t decide whether the latter is behaviour I want or not.

Should I do a tiny PR to switch the INFO behaviour?

[nedned]

Yeah there’s not really a good place to apply a new loglevel after run_server. A workaround could be to set dev_tools_silence_routes_logging=False in the run_server call. And if you do actually want the server routes being silenced, you could do it yourself manually:

logging.getLogger('werkzeug').setLevel(logging.ERROR)

My thoughts are that the app.logger shouldn’t be changed from the default DEBUG level inside of enable_dev_tools, certainly not due to the value of dev_tools_silence_routes_logging. Perhaps that line should just be removed.

Perhaps create an issue first, linking to this conversation? then if you’re up for it you could submit a PR. That way there’s a place for the discussion to happen.

[clare]

Done, https://github.com/plotly/dash/issues/532 . Thanks @nedned !

As an aside, if I want the flask logger for any reason, does it make more sense to access logging.getLogger('werkzeug') or app.server.logger? I’m guessing that app.server.logger is not really used by anything as it would usually be the application logger, and for Dash we instead use app.logger? I’m just not sure if some layer of Flask might log to it.