admin container logs sql errors and authentication does not work

daniel-jirca commented 3 years ago

Thank you for opening an issue with Mailu. Please understand that issues are meant for bugs and enhancement-requests. For user-support questions, reach out to us on matrix.

To be able to help you best, we need some more information.

Before you open your issue

[X] Check if no issue or pull-request for this already exists.
[X] Check documentation and FAQ. (Tip, use the search function on the documentation page)
[X] You understand Mailu is made by volunteers in their free time — be conscise, civil and accept that delays can occur.
[X] The title of the issue should be short and simple. It should contain specific terms related to the actual issue. Be specific while writing the title.

Environment & Versions

Environment

[X] docker-compose
[ ] kubernetes
[ ] docker swarm

Versions

Running version 1.8. Upgraded from 1.7.

Description

admin container logs sql errors and authentication does not work. Connection to mysql server (another host) worked fine on v1.7. Tested it via mysql-client from the VM that the mailu stack runs on and also from inside the admin container.

Replication Steps

Updated version from 1.7 to 1.8 in docker-compose.yml and redeployed services using docker compose.

Expected behaviour

Authentication should work and no sql / sqlalchemy errors should be logged in admin container.

Logs

admin_1 | INFO [alembic.runtime.migration] Context impl MySQLImpl. admin_1 | INFO [alembic.runtime.migration] Will assume non-transactional DDL. admin_1 | [2021-10-18 21:22:36 +0000] [8] [INFO] Starting gunicorn 19.9.0 admin_1 | [2021-10-18 21:22:36 +0000] [8] [INFO] Listening at: http://0.0.0.0:80 (8) admin_1 | [2021-10-18 21:22:36 +0000] [8] [INFO] Using worker: threads admin_1 | /usr/lib/python3.9/os.py:1023: RuntimeWarning: line buffering (buffering=1) isn't supported in binary mode, the default buffer size will be used admin_1 | return io.open(fd, *args, kwargs) admin_1 | [2021-10-18 21:22:36 +0000] [9] [INFO] Booting worker with pid: 9 admin_1 | [2021-10-18 21:22:38,121] ERROR in utils: cleaning admin_1 | [2021-10-18 21:25:03,268] ERROR in app: Exception on /internal/auth/email [GET] admin_1 | Traceback (most recent call last): admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1243, in _execute_context admin_1 | self.dialect.do_execute( admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/engine/default.py", line 552, in do_execute admin_1 | cursor.execute(statement, parameters) admin_1 | File "/usr/lib/python3.9/site-packages/MySQLdb/cursors.py", line 206, in execute admin_1 | res = self._query(query) admin_1 | File "/usr/lib/python3.9/site-packages/MySQLdb/cursors.py", line 312, in _query admin_1 | db.query(q) admin_1 | File "/usr/lib/python3.9/site-packages/MySQLdb/connections.py", line 224, in query admin_1 | _mysql.connection.query(self, query) admin_1 | MySQLdb._exceptions.OperationalError: (2000, 'Unknown MySQL error') admin_1 | admin_1 | The above exception was the direct cause of the following exception: admin_1 | admin_1 | Traceback (most recent call last): admin_1 | File "/usr/lib/python3.9/site-packages/flask/app.py", line 2292, in wsgi_app admin_1 | response = self.full_dispatch_request() admin_1 | File "/usr/lib/python3.9/site-packages/flask/app.py", line 1815, in full_dispatch_request admin_1 | rv = self.handle_user_exception(e) admin_1 | File "/usr/lib/python3.9/site-packages/flask/app.py", line 1718, in handle_user_exception admin_1 | reraise(exc_type, exc_value, tb) admin_1 | File "/usr/lib/python3.9/site-packages/flask/_compat.py", line 35, in reraise admin_1 | raise value admin_1 | File "/usr/lib/python3.9/site-packages/flask/app.py", line 1813, in full_dispatch_request admin_1 | rv = self.dispatch_request() admin_1 | File "/usr/lib/python3.9/site-packages/flask/app.py", line 1799, in dispatch_request admin_1 | return self.view_functions[rule.endpoint](req.view_args) admin_1 | File "/app/mailu/internal/views/auth.py", line 24, in nginx_authentication admin_1 | headers = nginx.handle_authentication(flask.request.headers) admin_1 | File "/app/mailu/internal/nginx.py", line 58, in handle_authentication admin_1 | for token in user.tokens: admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/orm/attributes.py", line 276, in get admin_1 | return self.impl.get(instancestate(instance), dict) admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/orm/attributes.py", line 682, in get admin1 | value = self.callable(state, passive) admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/orm/strategies.py", line 722, in _load_for_state admin_1 | return self._emit_lazyload( admin_1 | File "", line 1, in admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/orm/strategies.py", line 863, in _emit_lazyload admin_1 | q(session) admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/ext/baked.py", line 531, in all admin_1 | return list(self) admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/ext/baked.py", line 434, in iter admin_1 | return q._execute_and_instances(context) admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/orm/query.py", line 3342, in _execute_and_instances admin_1 | result = conn.execute(querycontext.statement, self._params) admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 988, in execute admin_1 | return meth(self, multiparams, params) admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/sql/elements.py", line 287, in _execute_on_connection admin_1 | return connection._execute_clauseelement(self, multiparams, params) admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1101, in _execute_clauseelement admin_1 | ret = self._execute_context( admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1247, in _execute_context admin_1 | self._handle_dbapi_exception( admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1466, in _handle_dbapi_exception admin_1 | util.raise_from_cause(sqlalchemy_exception, exc_info) admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/util/compat.py", line 383, in raise_from_cause admin_1 | reraise(type(exception), exception, tb=exc_tb, cause=cause) admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/util/compat.py", line 128, in reraise admin_1 | raise value.with_traceback(tb) admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1243, in _execute_context admin_1 | self.dialect.do_execute( admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/engine/default.py", line 552, in do_execute admin_1 | cursor.execute(statement, parameters) admin_1 | File "/usr/lib/python3.9/site-packages/MySQLdb/cursors.py", line 206, in execute admin_1 | res = self._query(query) admin_1 | File "/usr/lib/python3.9/site-packages/MySQLdb/cursors.py", line 312, in _query admin_1 | db.query(q) admin_1 | File "/usr/lib/python3.9/site-packages/MySQLdb/connections.py", line 224, in query admin_1 | _mysql.connection.query(self, query) admin_1 | sqlalchemy.exc.OperationalError: (MySQLdb._exceptions.OperationalError) (2000, 'Unknown MySQL error') admin_1 | [SQL: SELECT token.created_at AS token_created_at, token.updated_at AS token_updated_at, token.comment AS token_comment, token.id AS token_id, token.user_email AS token_user_email, token.password AS token_password, token.ip AS token_ip admin_1 | FROM token admin_1 | WHERE %s = token.user_email] admin_1 | [parameters: ('daniel.jirca@alecsa.design',)] admin_1 | (Background on this error at: http://sqlalche.me/e/e3q8) admin_1 | Exception during reset or similar admin_1 | Traceback (most recent call last): admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 739, in _rollback_impl admin_1 | self.engine.dialect.do_rollback(self.connection) admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/dialects/mysql/base.py", line 2227, in do_rollback admin_1 | dbapi_connection.rollback() admin_1 | MySQLdb._exceptions.OperationalError: (2000, 'Unknown MySQL error') admin_1 | admin_1 | The above exception was the direct cause of the following exception: admin_1 | admin_1 | Traceback (most recent call last): admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/pool/base.py", line 680, in _finalize_fairy admin_1 | fairy._reset(pool) admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/pool/base.py", line 865, in _reset admin_1 | self._reset_agent.rollback() admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1705, in rollback admin_1 | self._do_rollback() admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1743, in _do_rollback admin_1 | self.connection._rollback_impl() admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 741, in _rollback_impl admin_1 | self._handle_dbapi_exception(e, None, None, None, None) admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1466, in _handle_dbapi_exception admin_1 | util.raise_from_cause(sqlalchemy_exception, exc_info) admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/util/compat.py", line 383, in raise_from_cause admin_1 | reraise(type(exception), exception, tb=exc_tb, cause=cause) admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/util/compat.py", line 128, in reraise admin_1 | raise value.with_traceback(tb) admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 739, in _rollback_impl admin_1 | self.engine.dialect.do_rollback(self.connection) admin_1 | File "/usr/lib/python3.9/site-packages/sqlalchemy/dialects/mysql/base.py", line 2227, in do_rollback admin_1 | dbapi_connection.rollback() admin_1 | sqlalchemy.exc.OperationalError: (MySQLdb._exceptions.OperationalError) (2000, 'Unknown MySQL error') admin_1 | (Background on this error at: http://sqlalche.me/e/e3q8)

nextgens commented 3 years ago

"Unknown MySQL error" sounds like not our bug.

Have you checked the mysql server logs?

See https://dba.stackexchange.com/questions/91712/whats-causing-this-error-2000-hy000-unknown-mysql-error We may have upgraded the mysql client and it may use a different SSL provider. I suggest you do check whether you are using mysql_native_password or sha256_password

daniel-jirca commented 3 years ago

I don't know what happened, but it looks like v1.8 introduced a breaking change for setups using mariadb 10.5. 1.7 worked fine and could connect without issues, v1.8 didn't. I took this opportunity to migrate to postgres.

nextgens commented 3 years ago

Are you able/willing to investigate further on what exactly broke? If so, can you check/confirm whether it's my guess above?

BTW, I hope that you haven't migrated to the postgresql image we ship because that's deprecated and will be going away soon.

stale[bot] commented 2 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

stale[bot] commented 2 years ago

This issue has not seen activity since as it has become stale. Stale issues are automatically closed after 14 days.

Mailu / Mailu