It seems when logging.info
is called, a root handler is created and other loggers' logging appear twice due to propagation.
import sysimport loggingfrom flask import Flaskapp = Flask(__name__)app.logger.setLevel(logging.DEBUG)# logging.basicConfig(level=logging.DEBUG)logging.getLogger().setLevel(logging.DEBUG)log = logging.getLogger(__name__)if not log.handlers: log.setLevel(logging.DEBUG) formatter = logging.Formatter(fmt="%(asctime)s %(levelname)s %(module)s: %(message)s", datefmt="%H:%M:%S") handler = logging.StreamHandler(sys.stdout) handler.setLevel(logging.DEBUG) handler.setFormatter(formatter) log.addHandler(handler)@app.route('/')def test_logging(): logging.info('root logging') app.logger.info('app.logger') logging.getLogger('flask.app').info('flask.app') log.info('module log') return 'Test logging'from more import app as more_appapp.register_blueprint(more_app, url_prefix='/')if __name__ == '__main__': print('started') app.run(host='127.0.0.1', port=8088, debug=True)
Output
INFO:root:root logging
[2019-04-25 12:52:03,892] INFO in test: app.logger
INFO:flask.app:app.logger
[2019-04-25 12:52:03,893] INFO in test: flask.app
INFO:flask.app:flask.app
12:52:03 INFO test: module log
INFO:__main__:module log
Solution 1: don't use root logging
@app.route('/')def test_logging(): # logging.info('root logging') app.logger.info('app.logger') logging.getLogger('flask.app').info('flask.app') log.info('module log') return 'Test logging'
Output
[2019-04-25 12:52:43,979] INFO in test: app.logger
[2019-04-25 12:52:43,979] INFO in test: flask.app
12:52:43 INFO test: module log
Solution 2: prevent propagation to root
app.logger.propagate = Falselog.propagate = False@app.route('/')def test_logging(): logging.info('root logging') app.logger.info('app.logger') logging.getLogger('flask.app').info('flask.app') log.info('module log') return 'Test logging'
Output
INFO:root:root logging
[2019-04-25 12:54:36,079] INFO in test: app.logger
[2019-04-25 12:54:36,080] INFO in test: flask.app
12:54:36 INFO test: module log