Flask logging - Cannot get it to write to a file
Asked Answered
S

7

74

Ok, here's the code where I setup everything:

if __name__ == '__main__':
    app.debug = False

    applogger = app.logger

    file_handler = FileHandler("error.log")
    file_handler.setLevel(logging.DEBUG)

    applogger.setLevel(logging.DEBUG)
    applogger.addHandler(file_handler)

    app.run(host='0.0.0.0')

What happens is

  1. error.log gets created
  2. Nothing is ever written to it
  3. Despite not adding a StreamHandler and setting debug to false I still get everything to STDOUT (this might be correct, but still seems weird)

Am I totally off here somewhere or what is happening?

Salient answered 19/7, 2013 at 9:46 Comment(0)
P
129

Why not do it like this:

if __name__ == '__main__':
    init_db()  # or whatever you need to do

    import logging
    logging.basicConfig(filename='error.log',level=logging.DEBUG)

    app.run(host="0.0.0.0")

If you now start you application, you'll see that error.log contains:

INFO:werkzeug: * Running on http://0.0.0.0:5000/

For more info, visit http://docs.python.org/2/howto/logging.html

Okay, as you insist that you cannot have two handler with the method I showed you, I'll add an example that makes this quite clear. First, add this logging code to your main:

import logging, logging.config, yaml
logging.config.dictConfig(yaml.load(open('logging.conf')))

Now also add some debug code, so that we see that our setup works:

logfile    = logging.getLogger('file')
logconsole = logging.getLogger('console')
logfile.debug("Debug FILE")
logconsole.debug("Debug CONSOLE")

All what is left is the "logging.conf" program. Let's use that:

version: 1
formatters:
  hiformat:
    format: 'HI %(asctime)s - %(name)s - %(levelname)s - %(message)s'
  simple:
    format: '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
handlers:
  console:
    class: logging.StreamHandler
    level: DEBUG
    formatter: hiformat
    stream: ext://sys.stdout
  file:
    class: logging.FileHandler
    level: DEBUG
    formatter: simple
    filename: errors.log
loggers:
  console:
    level: DEBUG
    handlers: [console]
    propagate: no
  file:
    level: DEBUG
    handlers: [file]
    propagate: no
root:
  level: DEBUG
  handlers: [console,file]

This config is more complicated than needed, but it also shows some features of the logging module.

Now, when we run our application, we see this output (werkzeug- and console-logger):

HI 2013-07-22 16:36:13,475 - console - DEBUG - Debug CONSOLE
HI 2013-07-22 16:36:13,477 - werkzeug - INFO -  * Running on http://0.0.0.0:5000/

Also note that the custom formatter with the "HI" was used.

Now look at the "errors.log" file. It contains:

2013-07-22 16:36:13,475 - file - DEBUG - Debug FILE
2013-07-22 16:36:13,477 - werkzeug - INFO -  * Running on http://0.0.0.0:5000/
Paresis answered 22/7, 2013 at 10:15 Comment(6)
Because I actually aim to implement several handlers that log at different levels and this approach wouldn't get me farSalient
@fleshgolem: you still can create several handlers. Just do that directly with Python's logging.Paresis
@fleshgolem: look at the URL I have you and search for logging.conf. There you'll see how to create a second logger. There you have the loggers 'root' and 'simpleExample', both can have different log-levels, for example.Paresis
Well, I'm not here to fight and that IS a very nice and detailed answer, so have your checkmarkSalient
This isn't really using the app.logger that flask provides.Inhumanity
Problem with app.logger is that it is completely hardcoded. At least as of Flask 0.12.2 the logger settings of Flask (log level, log format and log output streams) are hardcoded in flask/logging.py and impossible to change without overriding app.logger property and writing custom implementation.Transverse
S
16

Ok, my failure stemmed from two misconceptions:

1) Flask will apparently ignore all your custom logging unless it is running in production mode

2) debug=False is not enough to let it run in production mode. You have to wrap the app in any sort of WSGI server to do so

After i started the app from gevent's WSGI server (and moving logging initialization to a more appropriate place) everything seems to work fine

Salient answered 22/7, 2013 at 12:27 Comment(3)
Your conclusion is wrong. The code I suggested to you runs a) with the built-in server, b) with Testing and/or debug mode, c) with several handlers. Additionally, your question was originally "Cannot get it to write to a file", and that question has been solved by by me. Unfortunately, you enlarged your question midway and wanted something different ... next time, I'd suggest that you describe your problem way more precisely.Paresis
I don't entirely agree. I asked, why flask's internal logger wouldn't write to a file, you supplied a solution that circumvents that logger. Yes it works, but I don't see it as a precise answer. I agree though, that I stated my problem badly. I will just leave both open, so anyone who finds this might find help in any of the twoSalient
There is no "flask internal logger". Flask is using (and configuring) the logger in Python's logging module. I actually found the Flask documentation on logging confusing, until I saw the statement "from logging import getLogger, ..." in flask/logging.py. From then on it was easy, because Python's logging module is very nicely documented. So no, I don't circumvent Flask's logger. If I would, how could Flask's log output possible end up in errors.log?Paresis
S
13

The output you see in the console of your app is from the underlying Werkzeug logger that can be accessed through logging.getLogger('werkzeug').

Your logging can function in both development and release by also adding handlers to that logger as well as the Flask one.

More information and example code: Write Flask Requests to an Access Log.

Supralapsarian answered 19/4, 2014 at 18:20 Comment(4)
Took me a while to discover this one my own, the 'werkzeug' logger is where all the actual http layed logging occurs. Unfortunately it doesn't format the logs and instead pushes '%s - - [%s] %s\n' % pre-formatted into the logger. So if you want to same style logs you'll need to recreate that formatting locally or call the werkzeug._internal._log method.Jalousie
For me, the logging.Logger.manager.loggerDict did not contain the werkzeug log and none of my 'top-of-the-module' config worked until I decorated it with @app.before_first_request as per @David's answer.Ptyalism
Thank you! This is the only information that allowed me to move flask logging to a syslogger.Congelation
For all those wondering: this is the correct answer and by far the simplest one. If you want to access Flasks's logger, it is this one.Saltworks
V
7

This works:

if __name__ == '__main__':
    import logging
    logFormatStr = '[%(asctime)s] p%(process)s {%(pathname)s:%(lineno)d} %(levelname)s - %(message)s'
    logging.basicConfig(format = logFormatStr, filename = "global.log", level=logging.DEBUG)
    formatter = logging.Formatter(logFormatStr,'%m-%d %H:%M:%S')
    fileHandler = logging.FileHandler("summary.log")
    fileHandler.setLevel(logging.DEBUG)
    fileHandler.setFormatter(formatter)
    streamHandler = logging.StreamHandler()
    streamHandler.setLevel(logging.DEBUG)
    streamHandler.setFormatter(formatter)
    app.logger.addHandler(fileHandler)
    app.logger.addHandler(streamHandler)
    app.logger.info("Logging is set up.")
    app.run(host='0.0.0.0', port=8000, threaded=True)
Volsci answered 17/11, 2015 at 13:13 Comment(1)
It looks bulky and confusing to be honest. How about using dictConfig ?Was
P
5

I didn't like the other answers so I kept at it and it seems like I had to make my logging config AFTER Flask did it's own setup.

@app.before_first_request
def initialize():

    logger = logging.getLogger("your_package_name")
    logger.setLevel(logging.DEBUG)
    ch = logging.StreamHandler()
    ch.setLevel(logging.DEBUG)
    formatter = logging.Formatter(
    """%(levelname)s in %(module)s [%(pathname)s:%(lineno)d]:\n%(message)s"""
    )
    ch.setFormatter(formatter)
    logger.addHandler(ch)

My app is structured like

/package_name
    __main__.py <- where I put my logging configuration
    __init__.py <- conveniance for myself, not necessary
    /tests
    /package_name <- Actual flask app
    __init__.py
    /views
    /static
    /templates
    /lib

Following these directions http://flask.pocoo.org/docs/0.10/patterns/packages/

Pericope answered 23/3, 2016 at 21:6 Comment(1)
My problem was not about logging to file but combining module logs with Flask logs in Docker with filtering, though the reason I couldn't get it to work seems to be the same (Flask usurping the logger). This answer gave me what I needed!Ptyalism
C
4

Why not take a dive in the code and see...

The module we land on is flask.logging.py, which defines a function named create_logger(app). Inspecting that function will give a few clues as to potential culprits when troubleshooting logging issues with Flask.

EDIT: this answer was meant for Flask prior to version 1. The flask.logging.py module has considerably changed since then. The answer still helps with some general caveats and advices regarding python logging, but be aware that some of Flask's peculiarities in that regard have been addressed in version 1 and might no longer apply.

The first possible cause of conflicts in that function is this line:

logger = getLogger(app.logger_name)

Let's see why:

The variable app.logger_name is set in the Flask.__init__() method to the value of import_name, which is itself the receiving parameter of Flask(__name__). That is app.logger_name is assigned the value of __name__, which will likely be the name of your main package, let's for this example call it 'awesomeapp'.

Now, imagine that you decided to configure and create your own logger manually. What do you think the chances are that if your project is named "awesomeapp" you would also use that name to configure your logger, I think it's pretty likely.

my_logger = logging.getLogger('awesomeapp') # doesn't seem like a bad idea
fh = logging.FileHandler('/tmp/my_own_log.log')
my_logger.setLevel(logging.DEBUG)
my_logger.addHandler(fh)

It makes sense to do this... except for a few problems.

When the Flask.logger property is invoked for the first time it will in turn call the function flask.logging.create_logger() and the following actions will ensue:

logger = getLogger(app.logger_name)

Remember how you named your logger after the project and how app.logger_name shares that name too? What happens in the line of code above is that the function logging.getLogger() has now retrieved your previously created logger and the following instructions are about to mess with it in a way that will have you scratching your head later. For instance

del logger.handlers[:]

Poof, you just lost all the handlers you may have previously registered with your logger.

Other things that happen within the function, without going much into details. It creates and registers two logging.StreamHandler objects that can spit out to sys.stderr and/or Response objects. One for log level 'debug' and another for 'production'.

class DebugLogger(Logger):
    def getEffectiveLevel(self):
        if self.level == 0 and app.debug:
            return DEBUG
        return Logger.getEffectiveLevel(self)

class DebugHandler(StreamHandler):
    def emit(self, record):
        if app.debug and _should_log_for(app, 'debug'):
            StreamHandler.emit(self, record)

class ProductionHandler(StreamHandler):
    def emit(self, record):
        if not app.debug and _should_log_for(app, 'production'):
            StreamHandler.emit(self, record)

debug_handler = DebugHandler()
debug_handler.setLevel(DEBUG)
debug_handler.setFormatter(Formatter(DEBUG_LOG_FORMAT))

prod_handler = ProductionHandler(_proxy_stream)
prod_handler.setLevel(ERROR)
prod_handler.setFormatter(Formatter(PROD_LOG_FORMAT))

logger.__class__ = DebugLogger
logger.addHandler(debug_handler)
logger.addHandler(prod_handler)

With the above details to light it should become clearer why our manually configured logger and handlers misbehave when Flask gets involved. The new information gives us new options though. If you still want to keep separate handlers, the simplest approach is to name your logger to something different than the project (e.g. my_logger = getLogger('awesomeapp_logger') ). Another approach, if you want to be consistent with the logging protocols in Flask, is to register a logging.FileHandler object on Flask.logger using a similar approach to Flask.

import logging
def set_file_logging_handler(app):

    logging_path = app.config['LOGGING_PATH']

    class DebugFileHandler(logging.FileHandler):
        def emit(self, record):
            # if your app is configured for debugging
            # and the logger has been set to DEBUG level (the lowest)
            # push the message to the file
            if app.debug and app.logger.level==logging.DEBUG:
                super(DebugFileHandler, self).emit(record)

    debug_file_handler = DebugFileHandler('/tmp/my_own_log.log')
    app.logger.addHandler(debug_file_handler)

app = Flask(__name__)
# the config presumably has the debug settings for your app
app.config.from_object(config)
set_file_logging_handler(app)

app.logger.info('show me something')
Carpio answered 14/12, 2017 at 8:10 Comment(6)
Hello Michael. You have mentioned "When the Flask.logger property is invoked for the first time it will in turn call the function flask.logging.create_logger()" - can you tell me exactly when Flask.logger is invoked? Is it when the flask app is initialized using app = Flask(__name__) or is it when a call is made to the flask app logger (example: app.logger.info('test') ?Autonomous
@Autonomous I haven't looked at the code in a while, but I think it's the latter. It would not make sense to create an instance of the logger if you're not using it. Look in the source if Flask has a @property named logger. That's where I presume the code would start.Carpio
In the app.py there is this @locked_cached_property with function def logger(self): which is responsible for the logic of checking/adding logger/handler. But I cannot figure out who or how that function is invoked - github.com/pallets/flask/blob/…Autonomous
@Autonomous @property is the pythonic way of implementing getters/setters/deleters. Have a look here to learn about them #6618502. If you don't understand the @property syntax, look into python decorators. You can learn to use property() to implement getters/setters without learning how it works underneath, which involves to peel off a few more layers (see python descriptor protocol). While the property() function is native to python, locked_cache_property() seems to be a specialization from flask.Carpio
It's a decorator (github.com/pallets/flask/blob/…) that converts the fucntion into lazy properly. But no where does it mention as to when the create_logger is called. Any advice plesse?Autonomous
@Autonomous The explanation might be a bit long for this one, can you join on this chat room chat.stackoverflow.com/rooms/211241/flask-logging-decorator?Carpio
H
0

Logging Quick start

-- This code will not work with more than one log file inside a class/or import

import logging
import os # for Cwd path 
path = os.getcwd()


logFormatStr = '%(asctime)s  %(levelname)s - %(message)s'
logging.basicConfig(filename=path + '\logOne.log', format=logFormatStr, level=logging.DEBUG), logging.info('default message')

for Multiple logging file

creating a instance of logging using logging.getLogger() method---

  1. for each logger file required one instance of logging
  2. we can create multiple log file but not with same instance

Create new logger instance with name or Hardcore_String ----preferred (name) this will specify exact class from where it call

logger = logging.getLogger(__name__)
logger.setLevel(logging.INFO)

type of logging -- INFO, DEBUG, ERROR, CRITICAL, WARNING

DEBUG----Detailed information, typically of interest only when diagnosing problems.

INFO----Confirmation that things are working as expected.

WARNING----An indication that something unexpected happened, or indicative of some problem in the near future (e.g. ‘disk space low’). The software is still working as expected.

ERROR----Due to a more serious problem, the software has not been able to perform some function.

CRITICAL----A serious error, indicating that the program itself may be unable to continue running.

Create New Formatter

format = logging.Formatter('%(asctime)s %(levelname)s - %(message)s')

create new file Handler

file_handel = logging.FileHandler(path + '\logTwo.log')

set format to FileHandler & add file_handler to logging instance [logger]

file_handel.setFormatter(format)
logger.addHandler(file_handel)

add a message to logOne.log file and logTwo.log with respective setlevel

logger.info("message for logOne")
logging.debug(" message for logTwo")

for more details

Harvison answered 31/7, 2020 at 18:56 Comment(0)

© 2022 - 2024 — McMap. All rights reserved.