[doc] Postgresql: Can't reconnect until invalid transaction is rolled back

Issue #358 resolved
André Klitzing created an issue

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}]]

Comments (17)

  1. Thomas De Schampheleire

    I think there must be one or more other tracebacks and/or errors before this point, could you check the log?

  2. André Klitzing reporter

    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
    

  3. André Klitzing reporter

    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
    

  4. Mads Kiilerich

    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…

  5. Mads Kiilerich

    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?

  6. Thomas De Schampheleire

    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.

  7. André Klitzing reporter

    No problem with gearbox.

    Could you provide your uwsgi and vassal config?

    How did you provide celery?

  8. Thomas De Schampheleire

    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).

  9. Mads Kiilerich

    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.

  10. Mads Kiilerich

    How could docs be changed to help this? The generated .ini for uwsgi already has

    lazy = true                            ; App *must* be loaded in workers - db connections can't be shared
    

    (and 269ba8809002 clarify how to avoid a slightly similar uwsgi problem)

  11. Thomas De Schampheleire

    I was referring to your comment “It would be nice to get a small section in the documentation about how to use uwsgi.”, and in general some general advice on different webservers and the deployment model. In the past I have seen some good docs on another project’s website but I don’t immediately recall which.

    Section https://kallithea.readthedocs.io/en/stable/overview.html#web-server is a good start but could be expanded.

  12. Mads Kiilerich

    I will propose something.

    The content of the .ini is now tells me enough about how to use uwsgi to get me started. I think we just need to hint that the templates should be used.

  13. Log in to comment