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:

But in the apache staging environment, the database reacts like this to the same several dozen requests:
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.
