Issue #358: [doc] Postgresql: Can't reconnect until invalid transaction is rolled back
| Reported by: | André Klitzing |
| State: | resolved |
| Created on: | 2020-02-07 11:11 |
| Updated on: | 2020-06-18 19:24 |
Description
We have a fresh installation of Kallithea 0.5.2 with Postgresql 11. We uses uwsgi and nginx. The WebUI can be used. Sometimes the server throws a “Internal Server Error” if a single user refreshes the Browser multiple times.
Traceback (most recent call last):
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/tg/wsgiapp.py", line 82, in call
response = self.wrapped_dispatch(controller, environ, context)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/tg/appwrappers/errorpage.py", line 104, in call
resp = self.next_handler(controller, environ, context)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/tg/appwrappers/caching.py", line 54, in call
return self.next_handler(controller, environ, context)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/tg/appwrappers/session.py", line 71, in call
response = self.next_handler(controller, environ, context)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/tg/appwrappers/i18n.py", line 71, in call
return self.next_handler(controller, environ, context)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/tg/wsgiapp.py", line 243, in _dispatch
return controller(environ, context)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/kallithea/lib/base.py", line 511, in call
ip_addr=ip_addr,
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/kallithea/lib/base.py", line 438, in _determine_auth_user
return AuthUser.from_cookie(session_authuser, ip_addr=ip_addr)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/kallithea/lib/auth.py", line 563, in from_cookie
dbuser=UserModel().get(cookie.get('user_id')),
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/kallithea/model/user.py", line 57, in get
return user.get(user_id)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 1004, in get
return self._get_impl(ident, loading.load_on_pk_identity)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 1116, in _get_impl
return db_load_fn(self, primary_key_identity)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/orm/loading.py", line 284, in load_on_pk_identity
return q.one()
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 3347, in one
ret = self.one_or_none()
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 3316, in one_or_none
ret = list(self)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/kallithea/lib/caching_query.py", line 81, in iter
return Query.iter(self)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 3389, in iter
return self._execute_and_instances(context)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 3414, in _execute_and_instances
result = conn.execute(querycontext.statement, self._params)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 982, in execute
return meth(self, multiparams, params)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/sql/elements.py", line 293, in _execute_on_connection
return connection._execute_clauseelement(self, multiparams, params)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1101, in _execute_clauseelement
distilled_params,
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1176, in _execute_context
e, util.text_type(statement), parameters, None, None
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1476, in _handle_dbapi_exception
util.raise_from_cause(sqlalchemy_exception, exc_info)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/util/compat.py", line 398, in raise_from_cause
reraise(type(exception), exception, tb=exc_tb, cause=cause)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1171, in _execute_context
conn = self._revalidate_connection()
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 457, in _revalidate_connection
"Can't reconnect until invalid "
StatementError: (sqlalchemy.exc.InvalidRequestError) Can't reconnect until invalid transaction is rolled back
[SQL: SELECT users.firstname AS users_firstname, users.email AS users_email, users.user_data AS users_user_data, users.user_id AS users_user_id, users.username AS users_username, users.password AS users_password, users.active AS users_active, users.admin AS users_admin, users.lastname AS users_lastname, users.last_login AS users_last_login, users.extern_type AS users_extern_type, users.extern_name AS users_extern_name, users.api_key AS users_api_key, users.created_on AS users_created_on
FROM users
WHERE users.user_id = %(param_1)s]
[parameters: [{'%(139880833321552 param)s': 2}]]
Attachments
Comments
Comment by Thomas De Schampheleire, on 2020-02-07 17:10
I think there must be one or more other tracebacks and/or errors before this point, could you check the log?
Comment by Thomas De Schampheleire, on 2020-02-07 17:12
Comment by André Klitzing, on 2020-02-08 15:23
Here the whole log after a restart. I want to the browser. Website shown without problems. One reload…. Internal Server Error.
running /usr/bin/uwsgi-core
*** has_emperor mode detected (fd: 7) ***
[uWSGI] getting INI configuration from k.ini
*** Starting uWSGI 2.0.18-debian (64bit) on [Sat Feb 8 16:21:24 2020] ***
compiled with version: 8.2.0 on 10 February 2019 02:42:46
os: Linux-4.19.0-6-amd64 #1 SMP Debian 4.19.67-2+deb10u2 (2019-11-11)
nodename: kallithea
machine: x86_64
clock source: unix
pcre jit disabled
detected number of CPU cores: 8
current working directory: /etc/uwsgi-emperor/vassals
detected binary path: /usr/bin/uwsgi-core
your processes number limit is 31794
your memory page size is 4096 bytes
*** WARNING: you have enabled harakiri without post buffering. Slow upload could be rejected on post-unbuffered webservers ***
detected max file descriptor number: 1024
lock engine: pthread robust mutexes
thunder lock: disabled (you can enable it with --thunder-lock)
uwsgi socket 0 inherited INET address 127.0.0.1:7777 fd 3
Python version: 2.7.16 (default, Oct 10 2019, 22:02:15) [GCC 8.3.0]
Python main interpreter initialized at 0x561ea7a9d180
python threads support enabled
your server socket listen backlog is limited to 120 connections
your mercy for graceful operations on workers is 60 seconds
mapped 947960 bytes (925 KB) for 12 cores
*** Operational MODE: preforking ***
2020-02-08 16:21:25.913 INFO [alembic.runtime.migration] Context impl PostgresqlImpl.
2020-02-08 16:21:25.913 INFO [alembic.runtime.migration] Will assume transactional DDL.
WSGI app 0 (mountpoint='') ready in 2 seconds on interpreter 0x561ea7a9d180 pid: 6158 (default app)
*** uWSGI is running in multiple interpreter mode ***
gracefully (RE)spawned uWSGI master process (pid: 6158)
spawned uWSGI worker 1 (pid: 11676, cores: 1)
spawned uWSGI worker 2 (pid: 11677, cores: 1)
Sat Feb 8 16:21:26 2020 - [emperor] vassal k.ini is ready to accept requests
spawned uWSGI worker 3 (pid: 11678, cores: 1)
spawned uWSGI worker 4 (pid: 11679, cores: 1)
spawned uWSGI worker 5 (pid: 11680, cores: 1)
spawned uWSGI worker 6 (pid: 11681, cores: 1)
spawned uWSGI worker 7 (pid: 11682, cores: 1)
spawned uWSGI worker 8 (pid: 11683, cores: 1)
spawned uWSGI worker 9 (pid: 11684, cores: 1)
spawned uWSGI worker 10 (pid: 11685, cores: 1)
spawned uWSGI worker 11 (pid: 11686, cores: 1)
spawned uWSGI worker 12 (pid: 11687, cores: 1)
*** Stats server enabled on /tmp/stats.kallithea.sock fd: 34 ***
announcing my loyalty to the Emperor...
Sat Feb 8 16:21:37 2020 - [emperor] vassal k.ini is now loyal
Traceback (most recent call last):
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/tg/wsgiapp.py", line 82, in __call__
response = self.wrapped_dispatch(controller, environ, context)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/tg/appwrappers/errorpage.py", line 104, in __call__
resp = self.next_handler(controller, environ, context)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/tg/appwrappers/caching.py", line 54, in __call__
return self.next_handler(controller, environ, context)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/tg/appwrappers/session.py", line 71, in __call__
response = self.next_handler(controller, environ, context)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/tg/appwrappers/i18n.py", line 71, in __call__
return self.next_handler(controller, environ, context)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/tg/wsgiapp.py", line 243, in _dispatch
return controller(environ, context)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/kallithea/lib/base.py", line 511, in __call__
ip_addr=ip_addr,
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/kallithea/lib/base.py", line 438, in _determine_auth_user
return AuthUser.from_cookie(session_authuser, ip_addr=ip_addr)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/kallithea/lib/auth.py", line 563, in from_cookie
dbuser=UserModel().get(cookie.get('user_id')),
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/kallithea/model/user.py", line 57, in get
return user.get(user_id)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 1004, in get
return self._get_impl(ident, loading.load_on_pk_identity)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 1116, in _get_impl
return db_load_fn(self, primary_key_identity)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/orm/loading.py", line 284, in load_on_pk_identity
return q.one()
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 3347, in one
ret = self.one_or_none()
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 3316, in one_or_none
ret = list(self)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/kallithea/lib/caching_query.py", line 81, in __iter__
return Query.__iter__(self)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 3389, in __iter__
return self._execute_and_instances(context)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 3414, in _execute_and_instances
result = conn.execute(querycontext.statement, self._params)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 982, in execute
return meth(self, multiparams, params)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/sql/elements.py", line 293, in _execute_on_connection
return connection._execute_clauseelement(self, multiparams, params)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1101, in _execute_clauseelement
distilled_params,
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1176, in _execute_context
e, util.text_type(statement), parameters, None, None
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1476, in _handle_dbapi_exception
util.raise_from_cause(sqlalchemy_exception, exc_info)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/util/compat.py", line 398, in raise_from_cause
reraise(type(exception), exception, tb=exc_tb, cause=cause)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1171, in _execute_context
conn = self._revalidate_connection()
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 457, in _revalidate_connection
"Can't reconnect until invalid "
StatementError: (sqlalchemy.exc.InvalidRequestError) Can't reconnect until invalid transaction is rolled back
[SQL: SELECT users.firstname AS users_firstname, users.email AS users_email, users.user_data AS users_user_data, users.user_id AS users_user_id, users.username AS users_username, users.password AS users_password, users.active AS users_active, users.admin AS users_admin, users.lastname AS users_lastname, users.last_login AS users_last_login, users.extern_type AS users_extern_type, users.extern_name AS users_extern_name, users.api_key AS users_api_key, users.created_on AS users_created_on
FROM users
WHERE users.user_id = %(param_1)s]
[parameters: [{'%(140311501440528 param)s': 2}]]
announcing my loyalty to the Emperor...
Sat Feb 8 16:21:38 2020 - [emperor] vassal k.ini is now loyal
Comment by André Klitzing, on 2020-02-08 15:26
After a logout and refresh sometimes the browser at the login screen:
2020-02-08 16:26:01.509 WARNI [kallithea.lib.auth] user is anonymous and NOT authenticated with regular auth @ HomeController:index
Traceback (most recent call last):
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/tg/wsgiapp.py", line 82, in __call__
response = self.wrapped_dispatch(controller, environ, context)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/tg/appwrappers/errorpage.py", line 104, in __call__
resp = self.next_handler(controller, environ, context)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/tg/appwrappers/caching.py", line 54, in __call__
return self.next_handler(controller, environ, context)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/tg/appwrappers/session.py", line 71, in __call__
response = self.next_handler(controller, environ, context)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/tg/appwrappers/i18n.py", line 71, in __call__
return self.next_handler(controller, environ, context)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/tg/wsgiapp.py", line 243, in _dispatch
return controller(environ, context)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/kallithea/lib/base.py", line 511, in __call__
ip_addr=ip_addr,
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/kallithea/lib/base.py", line 443, in _determine_auth_user
for plugin in auth_modules.get_auth_plugins()
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/kallithea/lib/auth_modules/__init__.py", line 322, in get_auth_plugins
for plugin_name in Setting.get_by_name("auth_plugins").app_settings_value:
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/kallithea/model/db.py", line 247, in get_by_name
.filter(cls.app_settings_name == key).scalar()
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 3377, in scalar
ret = self.one()
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 3347, in one
ret = self.one_or_none()
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 3316, in one_or_none
ret = list(self)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/kallithea/lib/caching_query.py", line 81, in __iter__
return Query.__iter__(self)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 3389, in __iter__
return self._execute_and_instances(context)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 3414, in _execute_and_instances
result = conn.execute(querycontext.statement, self._params)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 982, in execute
return meth(self, multiparams, params)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/sql/elements.py", line 293, in _execute_on_connection
return connection._execute_clauseelement(self, multiparams, params)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1101, in _execute_clauseelement
distilled_params,
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1176, in _execute_context
e, util.text_type(statement), parameters, None, None
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1476, in _handle_dbapi_exception
util.raise_from_cause(sqlalchemy_exception, exc_info)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/util/compat.py", line 398, in raise_from_cause
reraise(type(exception), exception, tb=exc_tb, cause=cause)
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1171, in _execute_context
conn = self._revalidate_connection()
File "/opt/kallithea/0.5.2/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 457, in _revalidate_connection
"Can't reconnect until invalid "
StatementError: (sqlalchemy.exc.InvalidRequestError) Can't reconnect until invalid transaction is rolled back
[SQL: SELECT settings.app_settings_value AS settings_app_settings_value, settings.app_settings_type AS settings_app_settings_type, settings.app_settings_id AS settings_app_settings_id, settings.app_settings_name AS settings_app_settings_name
FROM settings
WHERE settings.app_settings_name = %(app_settings_name_1)s]
[parameters: [immutabledict({})]]
announcing my loyalty to the Emperor...
Sat Feb 8 16:26:03 2020 - [emperor] vassal k.ini is now loyal
Comment by Mads Kiilerich, on 2020-02-08 15:28
I wonder if this could be related to 1a409593f352 or a1115795fabb , combined with interrupting responses before they have finished and thus before the server can clean up the usual way.
As a workaround, we could perhaps start each request by removing any previous transaction. But it would be nice to fix it at the root cause. A first step could perhaps be to assert explicitly that there can’t be any existing transaction when the request starts…
Comment by André Klitzing, on 2020-02-11 09:02
Anything I could try?
Comment by Mads Kiilerich, on 2020-02-11 12:34
Hmm. uwsgi seems great, but I never tried it.
To figure out if the problem comes with uwsgi or something else in your setup (and thus make it more reproducible), could you try to see if you can reproduce the problem with a plain gearbox serve?
Comment by Thomas De Schampheleire, on 2020-02-11 16:02
For the record, I am using uwsgi + postgresql + celery at work. The Kallithea version we are using is based on rev eee49a119592 which is almost equal to 0.5.0. We don’t see such issue.
Comment by André Klitzing, on 2020-02-11 17:28
No problem with gearbox.
Could you provide your uwsgi and vassal config?
How did you provide celery?
Comment by Thomas De Schampheleire, on 2020-02-12 08:13
We use docker with four containers: postgresql, kallithea, celery, rabbitmq.
The uwsgi configuration in our kallithea .ini file is quite basic, I think only thing we changed is the amount of workers.
We don’t use a separate web server like nginx currently, uwsgi handles that part now.
## UWSGI ## ## run with uwsgi --ini-paste-logged <inifile.ini> [uwsgi] socket = /tmp/uwsgi.sock master = true http = 0.0.0.0:5000 ## set as daemon and redirect all output to file #daemonize = ./uwsgi_kallithea.log ## master process PID pidfile = ./uwsgi_kallithea.pid ## stats server with workers statistics, use uwsgitop ## for monitoring, `uwsgitop 127.0.0.1:1717` stats = 127.0.0.1:1717 memory-report = true ## log 5XX errors log-5xx = true ## Set the socket listen queue size. listen = 128 ## Gracefully Reload workers after the specified amount of managed requests ## (avoid memory leaks). max-requests = 1000 ## enable large buffers buffer-size = 65535 ## socket and http timeouts ## http-timeout = 3600 socket-timeout = 3600 ## Log requests slower than the specified number of milliseconds. log-slow = 10 ## Exit if no app can be loaded. need-app = true ## Set lazy mode (load apps in workers instead of master). lazy = true ## scaling ## ## set cheaper algorithm to use, if not set default will be used cheaper-algo = spare ## minimum number of workers to keep at all times cheaper = 1 ## number of workers to spawn at startup cheaper-initial = 1 ## maximum number of workers that can be spawned workers = 32 ## how many workers should be spawned at a time cheaper-step = 1
I don’t know vassal and I thus think we don’t use it. (What is it and why would you need it?)
For celery there is also not something special. It is started in a separate container via ‘kallithea-cli celery-run’ and uses rabbitmq as broker.
Given that things work for me on 0.5.0, you could try to downgrade to that version to see if it makes a difference. Even though there are some database changes, they are only related to SSH repository access. If you don’t yet use this feature, you could just skip the database upgrade for this test, and set ignore_alembic_revision = True in the ini file under [app:main]. (Don’t forget to undo this change when this issue would be resolved).
Comment by André Klitzing, on 2020-02-13 11:26
Thanks…. lazy=true did the trick in my vassal.
Comment by Mads Kiilerich, on 2020-02-13 13:21
Cool. It would be nice to get a small section in the documentation about how to use uwsgi. kallithea-cli config-create new.ini http_server=uwsgi should perhaps also be better documented.