Flask app in apache environment creating duplicate log entries and escalating db conns

33 Views Asked by At

I have a python flask app which uses SQLAlchemy and flask-sqlalchemy. In the dev environment I use the built-in flask server connecting to a local postgres 14 db. The staging environment uses apache with mod-wsgi connecting to a postgres 12 db. The apache site config looks like this (anonymized):

<VirtualHost 192.168.1.100:80>
        ServerName staging.mysite.com
        ServerAdmin [email protected]
        DocumentRoot /var/www/mysite-staging

        WSGIDaemonProcess mysite-staging user=auser group=auser threads=2 display-name=mysite-staging python-path=/var/www/mysite-staging/ python-home=/usr/local/venvs/mysite

        WSGIScriptAlias / /var/www/mysite-staging/mysite.wsgi
        <Directory /var/www/mysite-staging>
                WSGIProcessGroup mysite-staging
                WSGIApplicationGroup %{GLOBAL}

                AllowOverride none
                Require all granted
        </Directory>
</VirtualHost>

Locally the startup logging looks like this, and there is no further repeat of these log entries on requests:

2023-11-19 09:27:26,499 {\config\logger.py:37} INFO: Logger active: app.db.models
2023-11-19 09:27:26,551 {\config\logger.py:37} INFO: Logger active: app
2023-11-19 09:27:26,551 {\app\__init__.py:44} INFO: Loading app config: DEVELOPMENT
2023-11-19 09:27:26,551 {\app\__init__.py:47} INFO: Loading testing config
2023-11-19 09:27:26,552 {\app\__init__.py:73} INFO: ENVIRONMENT = DEVELOPMENT

Then in the apache environment on a linux server, the logging does this on each request:

2023-11-19 09:22:03,483 {/config/logger.py:37} INFO: Logger active: app.db.models
2023-11-19 09:22:03,566 {/config/logger.py:37} INFO: Logger active: app
2023-11-19 09:22:03,566 {/app/__init__.py:44} INFO: Loading app config: STAGING
2023-11-19 09:22:03,567 {/app/__init__.py:55} INFO: Loading staging config
2023-11-19 09:22:03,567 {/app/__init__.py:73} INFO:  ENVIRONMENT = STAGING
2023-11-19 09:22:03,789 {/config/logger.py:37} INFO: Logger active: app
2023-11-19 09:22:03,789 {/config/logger.py:37} INFO: Logger active: app
2023-11-19 09:22:03,790 {/app/__init__.py:44} INFO: Loading app config: STAGING
2023-11-19 09:22:03,790 {/app/__init__.py:44} INFO: Loading app config: STAGING
2023-11-19 09:22:03,790 {/app/__init__.py:55} INFO: Loading staging config
2023-11-19 09:22:03,790 {/app/__init__.py:55} INFO: Loading staging config
2023-11-19 09:22:03,790 {/app/__init__.py:73} INFO:  ENVIRONMENT = STAGING
2023-11-19 09:22:03,790 {/app/__init__.py:73} INFO:  ENVIRONMENT = STAGING
2023-11-19 09:22:03,805 {/config/logger.py:37} INFO: Logger active: app
2023-11-19 09:22:03,805 {/config/logger.py:37} INFO: Logger active: app
2023-11-19 09:22:03,805 {/config/logger.py:37} INFO: Logger active: app
2023-11-19 09:22:03,805 {/app/__init__.py:44} INFO: Loading app config: STAGING
2023-11-19 09:22:03,805 {/app/__init__.py:44} INFO: Loading app config: STAGING
2023-11-19 09:22:03,805 {/app/__init__.py:44} INFO: Loading app config: STAGING
2023-11-19 09:22:03,805 {/app/__init__.py:55} INFO: Loading staging config
2023-11-19 09:22:03,805 {/app/__init__.py:55} INFO: Loading staging config
2023-11-19 09:22:03,805 {/app/__init__.py:55} INFO: Loading staging config
2023-11-19 09:22:03,806 {/app/__init__.py:73} INFO:  ENVIRONMENT = STAGING
2023-11-19 09:22:03,806 {/app/__init__.py:73} INFO:  ENVIRONMENT = STAGING
2023-11-19 09:22:03,806 {/app/__init__.py:73} INFO:  ENVIRONMENT = STAGING
2023-11-19 09:22:03,857 {/config/logger.py:37} INFO: Logger active: app
2023-11-19 09:22:03,857 {/config/logger.py:37} INFO: Logger active: app
2023-11-19 09:22:03,857 {/config/logger.py:37} INFO: Logger active: app
2023-11-19 09:22:03,857 {/config/logger.py:37} INFO: Logger active: app
2023-11-19 09:22:03,857 {/app/__init__.py:44} INFO: Loading app config: STAGING
2023-11-19 09:22:03,857 {/app/__init__.py:44} INFO: Loading app config: STAGING
2023-11-19 09:22:03,857 {/app/__init__.py:44} INFO: Loading app config: STAGING
2023-11-19 09:22:03,857 {/app/__init__.py:44} INFO: Loading app config: STAGING
2023-11-19 09:22:03,857 {/app/__init__.py:55} INFO: Loading staging config
2023-11-19 09:22:03,857 {/app/__init__.py:55} INFO: Loading staging config
2023-11-19 09:22:03,857 {/app/__init__.py:55} INFO: Loading staging config
2023-11-19 09:22:03,857 {/app/__init__.py:55} INFO: Loading staging config
2023-11-19 09:22:03,857 {/app/__init__.py:73} INFO:  ENVIRONMENT = STAGING
2023-11-19 09:22:03,857 {/app/__init__.py:73} INFO:  ENVIRONMENT = STAGING
2023-11-19 09:22:03,857 {/app/__init__.py:73} INFO:  ENVIRONMENT = STAGING
2023-11-19 09:22:03,857 {/app/__init__.py:73} INFO:  ENVIRONMENT = STAGING

Each time another request is made in the apache staging environment, the logging duplications increase by 4 - so if I make another call to the app the above will start at 5 duplicate entries, and end with 8 copies of each of the above log messages. In the apache site config I have tried changing the wsgi daemon threads to various numbers but it does not affect the number of duplications in the logs - it always increases by 4.

Possibly related, the dev database reacts like this to being hit with a few dozen requests: Dev environment database

But in the apache staging environment, the database reacts like this to the same several dozen requests:

Apache staging database

Basically all of the connections in the staging environment are in "idle" state, and will continue to pile up until it hits the maximum number of allowable connections, and then error out saying there are no connections available.

I'm not sure if the db connection problem is related to the log duplications or not.

Basically I'm hoping someone can offer some ideas of things to look at, things to test, or even just ideas of what might be going on here.

0

There are 0 best solutions below