Error connecting

[chiptopher]

Bug report

Sometimes when trying to connect, the website just falls over.

Actual behavior?

When trying to login, the login will be successful (in that, it won't show a login error), but won't actually log in.

Expected behavior?

It should log you in without error.

[chiptopher]

Looking at the logs, this is there error I've seen before.

2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] raise errors.OperationalError("MySQL Connection not available.")
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/mysql/connector/connection.py", line 813, in cursor
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] return self.connection.cursor(*args, **kwargs)
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/sqlalchemy/pool.py", line 977, in cursor
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] return self._dbapi_connection.cursor()
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/sqlalchemy/engine/default.py", line 954, in create_cursor
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] self.cursor = self.create_cursor()
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/sqlalchemy/engine/default.py", line 639, in _init_compiled
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] context = constructor(dialect, self, conn, *args)
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1127, in _execute_context
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] raise value.with_traceback(tb)
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 248, in reraise
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] reraise(type(exception), exception, tb=exc_tb, cause=cause)
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 265, in raise_from_cause
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] exc_info
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1413, in _handle_dbapi_exception
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] None, None)
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1132, in _execute_context
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] compiled_sql, distilled_params
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1060, in _execute_clauseelement
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] return connection._execute_clauseelement(self, multiparams, params)
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/sqlalchemy/sql/elements.py", line 269, in _execute_on_connection
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] return meth(self, multiparams, params)
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 948, in execute
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] result = conn.execute(querycontext.statement, self._params)
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/sqlalchemy/orm/query.py", line 3018, in _execute_and_instances
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] return self._execute_and_instances(context)
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/sqlalchemy/orm/query.py", line 2995, in __iter__
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] return list(res)
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/sqlalchemy/orm/query.py", line 2687, in __getitem__
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] ret = list(self[0:1])
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/sqlalchemy/orm/query.py", line 2895, in first
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] return db.session.query(User).filter_by(email=username).first()
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/app/scalio/users/model.py", line 28, in find_by_username
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] if username is None or not User.find_by_username(username):
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/app/scalio/users/controller.py", line 71, in get
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] resp = meth(*args, **kwargs)
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/flask_restful/__init__.py", line 595, in dispatch_request
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] return self.dispatch_request(*args, **kwargs)
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/flask/views.py", line 88, in view
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] resp = resource(*args, **kwargs)
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/flask_restful/__init__.py", line 480, in wrapper
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] return self.view_functions[rule.endpoint](**req.view_args)
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/flask/app.py", line 1799, in dispatch_request
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] rv = self.dispatch_request()
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/flask/app.py", line 1813, in full_dispatch_request
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] Traceback (most recent call last):
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] The above exception was the direct cause of the following exception:
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] mysql.connector.errors.OperationalError: MySQL Connection not available.
2019-04-03T07:41:13.575-04:00 [APP/PROC/WEB/0] [ERR] ERROR:flask.app:Exception on /api/user/authenticated [GET]
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] sqlalchemy.exc.InvalidRequestError: Can't reconnect until invalid transaction is rolled back
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] "Can't reconnect until invalid "
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 427, in _revalidate_connection
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] return self._revalidate_connection()
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 352, in connection
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] raise value
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 249, in reraise
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] util.reraise(*exc_info)
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1416, in _handle_dbapi_exception
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] self._handle_dbapi_exception(e, None, None, None, None)
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 354, in connection
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] self.engine.dialect.do_commit(self.connection)
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 724, in _commit_impl
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 726, in _commit_impl
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] self.connection._commit_impl()
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1674, in _do_commit
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] self._do_commit()
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1643, in commit
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] t[1].commit()
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/sqlalchemy/orm/session.py", line 471, in commit
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] self.transaction.commit()
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/sqlalchemy/orm/session.py", line 943, in commit
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] return getattr(self.registry(), name)(*args, **kwargs)
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/sqlalchemy/orm/scoping.py", line 153, in do
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] db.session.commit()
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/app/scalio/app.py", line 24, in commit
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] response = handler(response)
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/flask/app.py", line 2112, in process_response
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] response = self.process_response(response)
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/flask/app.py", line 1833, in finalize_request
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] return self.finalize_request(rv)
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/flask/app.py", line 1816, in full_dispatch_request
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] response = self.full_dispatch_request()
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] File "/home/vcap/deps/0/python/lib/python3.6/site-packages/flask/app.py", line 2292, in wsgi_app
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] Traceback (most recent call last):
2019-04-03T07:41:13.577-04:00 [APP/PROC/WEB/0] [ERR] ERROR:flask.app:Exception on /api/user/authenticated [GET]

Particularly, it looks like the issue is happening in the db.commit() after a request. The error also notes that there might be something wrong with the connection itself.

[chiptopher]

Hopefully addressed by de48b46.