Logging Documentation, Patterns & Extending

[nfarrar]

I've spent the last month digging through flask and building a large application. Figuring out and configuring logging has been one of the most difficult things to get under control. I still don't understand it well enough that I'm comfortable or have things configured the way I'd like.

When learning a new python package/framework/utility - the first thing I typically do is setup debug logging, so that I can see exactly what's going on. The more verbose the debugging messages are, the easier things are to figure out. Typically - debugging logs will dump information like:

• a configuration file was loaded
• a configuration value was set
• API providers have been initialized and are ready for use
• when API calls are performed, etc.

As far as I can tell, Flask doesn't do any of that - 'logs' are reserved for the instantiated flask application object itself - out of the box, running in debug mode - the only information I get out of the logs is that a request was received and answered. The debug logs don't seem to provide any information about flask's internal activities, things like:

• a flask object was instantiated
• a blueprint was registered
• a route was configured
• an extension was loaded
• an extension was configured
• extension specific things

These are all things I've had to "jump through hoops" to understand (while designing my application, application structure, application patterns, etc) - things that seem like they would have been much easier to understand, had logs been available. As I dig further into Flask Internals while building out my application further, there's more and more stuff I'd like to be dumping to my logs so I know exactly what's going on, internally.

As an initial attempt to set this up - I started by using logging_tree to dump out the logger heirarchy to see what's what. Based on that - I basically hooked the Config object (similar to how flasky is doing this). Then I read through all the logger docs I could find, I started putting logging statements all over my application code, for example:

    app.logger.debug('ENV:          %s' % app.config['ENV'])
    app.logger.debug('HOST_ADDRESS: %s' % app.config['HOST_ADDRESS'])
    app.logger.debug('HOST_PORT:    %s' % app.config['HOST_PORT'])
    app.logger.debug('SECRET_KEY:   %s' % app.config['SECRET_KEY'])
    app.logger.debug('PROJECT_ROOT: %s' % app.config['PROJECT_ROOT'])
    app.logger.debug('APP_ROOT:     %s' % app.config['APP_ROOT'])
    app.logger.debug('TMP_PATH:     %s' % app.config['TMP_PATH'])

This uses the default log format, which is very verbose (and is tailored to provide robust information about requests - not really great for what I'm trying to do here). Instead of getting 7 lines that that are tabularized and easy to read, this generates 28 lines, that not easy to scan for this use-case. I spent awhile trying to use app.logger as a logging.logger object, until I finally figured out (yes, it's in the docs, but a little counter-intuitive) that it's not actually a logging.logger object - it's actually a logging.StreamHandler() object.

Then I spent a bunch of time learning more about logging and structured logging and reading through Flask's source, trying to understand exactly what's going on here. I've got some basic experience with structured logging in python, but what's going on here was well above my head and not easy to adjust. I ended up finding the Flask.debug_log_format() API, and used that to set my debug message format to the standard log messaging format - but when dealing with requests - now I miss the old format - and there's logs of other information I'd like to start injecting into those debugging messages as well, that I don't want in my standard messages.

So now - I've been attempting to figure out a pattern that will let me do something like:

• Create a logging object that handles messages just for debugging messages related to my application setup & initialization - so I can dump things like:
  • when a flask object is instantiated (im working on dispatching multiplication wsgi applications, as apart of the same flask application)
  • things specific to flask objects that have been instantiated:
    • the configuration values
    • the blueprints
    • the routes
    • the models
• Create a separate request logger that:
  • uses a log format similar to flask's default log format (very robust, specific to debugging requests)
  • injects additional information about requests into the logging formatter
• I'm still trying to figure out how to make this less explicit in my application code, so that automatically display debugging information about what flask is doing, rather than having to put debugging statements all throughout my application code

I'm working through these things step by step, but they're definitely taking a long time - and unless I'm missing some documentation here or being very dense - these seem like a big challenge for user's new to to the Flask framwork. I've found some examples (by scouring google, github.com, and gist.github.com) that are helping me along, but nothing that really explains or walks through this kind of stuff.

So - am I missing some documentation here? Am I doing something that I shouldn't? Any suggestions or references you can point me to?

[davidism]

Thanks for writing up your experience. However, I'm not sure what the action item here is. All of Flask's setup is controlled by the user, including everything in the first two bullet lists; it seems redundant to tell the user that the code did what they just told it to do. On failures, you can use the interactive debugger to inspect each frame of the failure. Or you can attach your own debugger such as PyCharm and step through what's happening.

When logging things about your code, you should use standard logging. Get the logger for your module with logger = logging.getLogger(__name__), then log with it. If you need other information, attach a formatter to add that information, such as pulling attributes from request if a request is active.