I have a webapp using Python, Flask and Flask-Security-Too. When running locally against a deployed database (also in Azure) It's working as intended. When the application is deployed to Azure it also works nicely. However, after a period of time it will start to throw errors like the one below:
2021-11-25T08:33:20.676633302Z [2021-11-25 08:33:20 +0000] [8] [ERROR] Error handling request /login
2021-11-25T08:33:20.676686905Z Traceback (most recent call last):
2021-11-25T08:33:20.676694906Z File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1202, in _execute_context
2021-11-25T08:33:20.676700406Z conn = self._revalidate_connection()
2021-11-25T08:33:20.676705406Z File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 469, in _revalidate_connection
2021-11-25T08:33:20.676710407Z raise exc.InvalidRequestError(
2021-11-25T08:33:20.676715107Z sqlalchemy.exc.InvalidRequestError: Can't reconnect until invalid transaction is rolled back
2021-11-25T08:33:20.676720007Z
2021-11-25T08:33:20.676724408Z The above exception was the direct cause of the following exception:
2021-11-25T08:33:20.676729108Z
2021-11-25T08:33:20.676733508Z Traceback (most recent call last):
2021-11-25T08:33:20.676738108Z File "/usr/local/lib/python3.8/site-packages/gunicorn/workers/sync.py", line 134, in handle
2021-11-25T08:33:20.676742809Z self.handle_request(listener, req, client, addr)
2021-11-25T08:33:20.676747309Z File "/usr/local/lib/python3.8/site-packages/gunicorn/workers/sync.py", line 175, in handle_request
2021-11-25T08:33:20.676752109Z respiter = self.wsgi(environ, resp.start_response)
2021-11-25T08:33:20.676756710Z File "/usr/local/lib/python3.8/site-packages/flask/app.py", line 2464, in __call__
2021-11-25T08:33:20.676761610Z return self.wsgi_app(environ, start_response)
2021-11-25T08:33:20.676766110Z File "/usr/local/lib/python3.8/site-packages/flask/app.py", line 2450, in wsgi_app
2021-11-25T08:33:20.676770711Z response = self.handle_exception(e)
2021-11-25T08:33:20.676775311Z File "/usr/local/lib/python3.8/site-packages/flask_cors/extension.py", line 165, in wrapped_function
2021-11-25T08:33:20.676780011Z return cors_after_request(app.make_response(f(*args, **kwargs)))
2021-11-25T08:33:20.676784712Z File "/usr/local/lib/python3.8/site-packages/flask/app.py", line 1867, in handle_exception
2021-11-25T08:33:20.676789412Z reraise(exc_type, exc_value, tb)
2021-11-25T08:33:20.676794012Z File "/usr/local/lib/python3.8/site-packages/flask/_compat.py", line 39, in reraise
2021-11-25T08:33:20.676798612Z raise value
2021-11-25T08:33:20.676813213Z File "/usr/local/lib/python3.8/site-packages/flask/app.py", line 2447, in wsgi_app
2021-11-25T08:33:20.676818114Z response = self.full_dispatch_request()
2021-11-25T08:33:20.676822214Z File "/usr/local/lib/python3.8/site-packages/flask/app.py", line 1952, in full_dispatch_request
2021-11-25T08:33:20.676826514Z rv = self.handle_user_exception(e)
2021-11-25T08:33:20.676830615Z File "/usr/local/lib/python3.8/site-packages/flask_cors/extension.py", line 165, in wrapped_function
2021-11-25T08:33:20.676834915Z return cors_after_request(app.make_response(f(*args, **kwargs)))
2021-11-25T08:33:20.676840015Z File "/usr/local/lib/python3.8/site-packages/flask/app.py", line 1821, in handle_user_exception
2021-11-25T08:33:20.676844515Z reraise(exc_type, exc_value, tb)
2021-11-25T08:33:20.676848616Z File "/usr/local/lib/python3.8/site-packages/flask/_compat.py", line 39, in reraise
2021-11-25T08:33:20.676852916Z raise value
2021-11-25T08:33:20.676874217Z File "/usr/local/lib/python3.8/site-packages/flask/app.py", line 1950, in full_dispatch_request
2021-11-25T08:33:20.676878918Z rv = self.dispatch_request()
2021-11-25T08:33:20.676883218Z File "/usr/local/lib/python3.8/site-packages/flask/app.py", line 1936, in dispatch_request
2021-11-25T08:33:20.676888318Z return self.view_functions[rule.endpoint](**req.view_args)
2021-11-25T08:33:20.676892919Z File "/usr/local/lib/python3.8/site-packages/flask_security/decorators.py", line 436, in decorated
2021-11-25T08:33:20.676897419Z return fn(*args, **kwargs)
2021-11-25T08:33:20.676901819Z File "/usr/local/lib/python3.8/site-packages/flask_security/views.py", line 162, in login
2021-11-25T08:33:20.676906220Z if form.validate_on_submit():
2021-11-25T08:33:20.676910620Z File "/usr/local/lib/python3.8/site-packages/flask_wtf/form.py", line 100, in validate_on_submit
2021-11-25T08:33:20.676915220Z return self.is_submitted() and self.validate()
2021-11-25T08:33:20.676919720Z File "/usr/local/lib/python3.8/site-packages/flask_security/forms.py", line 450, in validate
2021-11-25T08:33:20.676924121Z self.user = find_user(self.email.data)
2021-11-25T08:33:20.676928321Z File "/usr/local/lib/python3.8/site-packages/flask_security/utils.py", line 829, in find_user
2021-11-25T08:33:20.676932921Z user = _datastore.find_user(
2021-11-25T08:33:20.676937122Z File "/usr/local/lib/python3.8/site-packages/flask_security/datastore.py", line 585, in find_user
2021-11-25T08:33:20.676941622Z return query.filter(subquery).first()
2021-11-25T08:33:20.676945822Z File "/usr/local/lib/python3.8/site-packages/sqlalchemy/orm/query.py", line 3429, in first
2021-11-25T08:33:20.676950422Z ret = list(self[0:1])
2021-11-25T08:33:20.676954623Z File "/usr/local/lib/python3.8/site-packages/sqlalchemy/orm/query.py", line 3203, in __getitem__
2021-11-25T08:33:20.676959023Z return list(res)
2021-11-25T08:33:20.676967724Z File "/usr/local/lib/python3.8/site-packages/sqlalchemy/orm/query.py", line 3535, in __iter__
2021-11-25T08:33:20.676972424Z return self._execute_and_instances(context)
2021-11-25T08:33:20.676976724Z File "/usr/local/lib/python3.8/site-packages/sqlalchemy/orm/query.py", line 3560, in _execute_and_instances
2021-11-25T08:33:20.676981224Z result = conn.execute(querycontext.statement, self._params)
2021-11-25T08:33:20.676985525Z File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1011, in execute
2021-11-25T08:33:20.676989925Z return meth(self, multiparams, params)
2021-11-25T08:33:20.676994525Z File "/usr/local/lib/python3.8/site-packages/sqlalchemy/sql/elements.py", line 298, in _execute_on_connection
2021-11-25T08:33:20.676999126Z return connection._execute_clauseelement(self, multiparams, params)
2021-11-25T08:33:20.677003426Z File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1124, in _execute_clauseelement
2021-11-25T08:33:20.677007926Z ret = self._execute_context(
2021-11-25T08:33:20.677012127Z File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1206, in _execute_context
2021-11-25T08:33:20.677016627Z self._handle_dbapi_exception(
2021-11-25T08:33:20.677020827Z File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1510, in _handle_dbapi_exception
2021-11-25T08:33:20.677025327Z util.raise_(
2021-11-25T08:33:20.677029528Z File "/usr/local/lib/python3.8/site-packages/sqlalchemy/util/compat.py", line 182, in raise_
2021-11-25T08:33:20.677034028Z raise exception
2021-11-25T08:33:20.677038128Z File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1202, in _execute_context
2021-11-25T08:33:20.677042729Z conn = self._revalidate_connection()
2021-11-25T08:33:20.677046929Z File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 469, in _revalidate_connection
2021-11-25T08:33:20.677051429Z raise exc.InvalidRequestError(
2021-11-25T08:33:20.677055629Z sqlalchemy.exc.StatementError: (sqlalchemy.exc.InvalidRequestError) Can't reconnect until invalid transaction is rolled back
2021-11-25T08:33:20.677061730Z [SQL: SELECT anon_1.user_id AS anon_1_user_id, anon_1.user_email AS anon_1_user_email, anon_1.user_username AS anon_1_user_username, anon_1.user_password AS anon_1_user_password, anon_1.user_active AS anon_1_user_active, anon_1.user_fs_uniquifier AS anon_1_user_fs_uniquifier, anon_1.user_confirmed_at AS anon_1_user_confirmed_at, anon_1.user_last_login_at AS anon_1_user_last_login_at, anon_1.user_current_login_at AS anon_1_user_current_login_at, anon_1.user_last_login_ip AS anon_1_user_last_login_ip, anon_1.user_current_login_ip AS anon_1_user_current_login_ip, anon_1.user_login_count AS anon_1_user_login_count, anon_1.user_tf_primary_method AS anon_1_user_tf_primary_method, anon_1.user_tf_totp_secret AS anon_1_user_tf_totp_secret, anon_1.user_tf_phone_number AS anon_1_user_tf_phone_number, anon_1.user_create_datetime AS anon_1_user_create_datetime, anon_1.user_update_datetime AS anon_1_user_update_datetime, anon_1.user_uuid AS anon_1_user_uuid, role_1.id AS role_1_id, role_1.name AS role_1_name, role_1.description AS role_1_description, role_1.permissions AS role_1_permissions, role_1.update_datetime AS role_1_update_datetime
2021-11-25T08:33:20.677072630Z FROM (SELECT TOP 1 [user].id AS user_id, [user].email AS user_email, [user].username AS user_username, [user].password AS user_password, [user].active AS user_active, [user].fs_uniquifier AS user_fs_uniquifier, [user].confirmed_at AS user_confirmed_at, [user].last_login_at AS user_last_login_at, [user].current_login_at AS user_current_login_at, [user].last_login_ip AS user_last_login_ip, [user].current_login_ip AS user_current_login_ip, [user].login_count AS user_login_count, [user].tf_primary_method AS user_tf_primary_method, [user].tf_totp_secret AS user_tf_totp_secret, [user].tf_phone_number AS user_tf_phone_number, [user].create_datetime AS user_create_datetime, [user].update_datetime AS user_update_datetime, [user].uuid AS user_uuid
2021-11-25T08:33:20.677078531Z FROM [user]
2021-11-25T08:33:20.677082731Z WHERE lower([user].email) = lower(?)) AS anon_1 LEFT OUTER JOIN (roles_users AS roles_users_1 JOIN role AS role_1 ON role_1.id = roles_users_1.role_id) ON anon_1.user_id = roles_users_1.user_id]
2021-11-25T08:33:20.677087431Z [parameters: [immutabledict({})]]
AFAIK, all the db.session's and user_datastore entities are either rolled back, commited and/or closed after they're used. Here's an example:
def create_user():
try:
current_app.logger.info('Creating admin user...')
setup_admin_user(current_app.user_datastore)
current_app.logger.info('Done!')
except IntegrityError as ie:
current_app.logger.warning('Failed to create admin user(s) as they already exists.')
db.session.rollback()
except Exception as e:
db.session.rollback()
raise e
finally:
db.session.close()
def setup_admin_user(usr_datastore):
if not usr_datastore.find_user(email="[email protected]"):
usr_datastore.create_user(email="[email protected]",
password=hash_password('password'),
roles=["admin"],
confirmed_at=datetime.datetime.utcnow())
usr_datastore.commit()
I also noticed that the parameters for the provided SQL are looking a bit suspicious. Sometimes there's a real parameter but the error message is still the same.
I'm confused as the query does work properly when executing it in the database and the Traceback does not mention any lines in the code I've written.
Any idea's on how I can fix this? I've tried bumping the versions for flask-sqlalchemy and flask-security-too to the latest stable versions.
Solved it by configuring a health check for the app service in Azure. The health check-endpoint will do a simple query to the database in order to keep it alive, which I believe was the problem.
def health_check():
role = current_app.user_datastore.find_role('dummy')
if role:
current_app.logger.info(f'[health_check] Found role {role.name}')
return jsonify(status='ok'), 200
return jsonify(status='failure'), 500