[FIXED] flask and gunicorn duplicated logging

Issue

I'm running a flask application served by gunicorn. I'm not sure why app.logger.info('logging here') is being logged twice in my log file.

In provision.py:

# provision.py
Class ProvisionService(object):
    ...
    def provision_order():
        ...
        app.logger.log('logging starts here')
        ...
    ...

Following is the log output in /logs/provision_app/app-api_error.log

[2021-03-18 11:54:35,810] INFO in provision: logging starts here
[2021-03-18 11:54:35 +0800] [13268] [INFO] logging starts here

My app service is setup as follow: provision-app.service

[Unit]
Description=gunicorn service for provision API
After=network.target

[Service]
User=provision
Group=provision
PIDFile=/var/provision/pid-provision-api
WorkingDirectory=/opt/provision
ExecStart=/opt/provision/bin/gunicorn \
    --pid /var/provision/pid-provision-api \
    --error-logfile /logs/provision_app/app-api_error.log \
    --access-logfile /logs/provision_app/app-api_access.log \
    --bind=127.0.0.1:8084 provision.api:app
ExecReload=/bin/kill -s HUP $MAINPID
ExecStop=/bin/kill -s TERM $MAINPID
PrivateTmp=true

[Install]
WantedBy=multi-user.target

init.py where I'm setting up the logging:

from flask import Flask
from flask_restful import Api
from flask_sqlalchemy import SQLAlchemy
from provision.conf import load_from_toml
import logging
import os.path

if os.path.isfile('/opt/provision/provision.toml'):
    config = load_from_toml('/opt/provision/provision.toml')
else:
    config = load_from_toml()

db = SQLAlchemy()

app = Flask(__name__)
api = Api(app)

app.config['SQLALCHEMY_TRACK_MODIFICATIONS'] = False
app.config['SQLALCHEMY_DATABASE_URI'] = config['mysql']['db_uri']
app.config['SQLALCHEMY_ENGINE_OPTIONS'] = {'pool_recycle': 3000, 'pool_pre_ping': True, }
db.init_app(app)


@app.before_first_request
def setup_logging():
    gunicorn_error_logger = logging.getLogger('gunicorn.error')
    app.logger.handlers.extend(gunicorn_error_logger.handlers)
    app.logger.setLevel(gunicorn_error_logger.level)

Any idea if there's some issues in the logging setup?

Solution

its possible that flask uses a default logger / handler despite configuring a custom one, I have these lines in my setup

from flask.logging import default_handler
app.logger.removeHandler(default_handler)  # use custom loggers instead

Let me know if that solves the issue

Answered By - c8999c 3f964f64