Enabling Celery breaks repo creation web interface update

holstf · November 30, 2020, 3:02pm

Hi,

First my system info:

Centos 7.9
Rhodecode CE 4.23.1
PGSQL 11
Redis 6.0.8 (downloaded from source and compiled it)

I have had a situation where setting

use_celery = false

gives me a functioning repository creation while

use_celery = true

breaks repository creation:

This screen never re-directs and navigation to Home gives a very short error message in the top. “Fetching repository in a failed state. Error 0” or something similar (shows less than a second).

I did do a sqlite to pgsql migration on this instance as described in the help in this forum.
So to my surprise, I saw in the rhodecode_celery.log that it still seems to be talking sqlite to the database since I see this in messages: “pysqlite2.dbapi2.IntegrityError”
(The redis/celery config was done before migration to pgqsl).

2020-11-30 14:41:22.134 [2163] INFO  [celery.worker.strategy] Received task: rhodecode.lib.celerylib.tasks.create_repo[214c7636-75c2-421c-86eb-5a8a75c38612]  
2020-11-30 14:41:22.136 [2290] INFO  [rhodecode.lib.celerylib.utils] Testing DB connection...
2020-11-30 14:41:22.367 [2290] INFO  [rhodecode.model.repo] creating repo my-test-repo-merc-7-    celery-test in /srv/rhodecode/repos/CM-Private/my-test-repo-merc-7-celery-test from url: ``
2020-11-30 14:41:22.448 [2290] INFO  [rhodecode.lib.audit_logger] AUDIT[]: Logging action: `repo.create` by user:id:2[admin] ip:None
2020-11-30 14:41:22.452 [2290] INFO  [celery.app.trace] Task   rhodecode.lib.celerylib.tasks.create_repo[214c7636-75c2-421c-86eb-5a8a75c38612] succeeded in 0.315703551751s: True
2020-11-30 14:51:34.207 [2163] INFO  [celery.worker.strategy] Received task: rhodecode.lib.celerylib.tasks.create_repo[827fcd2b-c47b-4b04-99f9-448452f5dd13]  
2020-11-30 14:51:34.209 [2289] INFO  [rhodecode.lib.celerylib.utils] Testing DB connection...
2020-11-30 14:51:34.257 [2289] INFO  [rhodecode.model.repo] creating repo Test-hg in /srv/rhodecode/repos/Test-hg from url: ``
2020-11-30 14:51:34.312 [2289] INFO  [rhodecode.lib.audit_logger] AUDIT[]: Logging action: `repo.create` by user:id:2[admin] ip:None
2020-11-30 14:51:34.317 [2289] INFO  [celery.app.trace] Task rhodecode.lib.celerylib.tasks.create_repo[827fcd2b-c47b-4b04-99f9-448452f5dd13] succeeded in 0.10731254518s: True
2020-11-30 14:51:54.071 [2163] INFO  [celery.worker.strategy] Received task: rhodecode.lib.celerylib.tasks.create_repo[e9bbbd00-0fcc-4213-a042-85addbe8f6c9]  
2020-11-30 14:51:54.073 [2299] INFO  [rhodecode.lib.celerylib.utils] Testing DB connection...
2020-11-30 14:51:54.245 [2299] ERROR [rhodecode.model.repo] Traceback (most recent call last):
  File "/opt/rhodecode/store/cnpzq6z5xjxzxw2m3d1cfb5yhpazscn5-python2.7-rhodecode-enterprise-ce-4.22.0/lib/python2.7/site-packages/rhodecode/model/repo.py", line 582, in _create_repo
perm_obj = self._create_default_perms(new_repo, private)
  File "/opt/rhodecode/store/cnpzq6z5xjxzxw2m3d1cfb5yhpazscn5-python2.7-rhodecode-enterprise-ce-4.22.0/lib/python2.7/site-packages/rhodecode/model/repo.py", line 69, in _create_default_perms
def_user = User.get_default_user()
  File "/opt/rhodecode/store/cnpzq6z5xjxzxw2m3d1cfb5yhpazscn5-python2.7-rhodecode-enterprise-ce-4.22.0/lib/python2.7/site-packages/rhodecode/model/db.py", line 1047, in get_default_user
user = User.get_by_username(User.DEFAULT_USER, cache=cache)
  File "/opt/rhodecode/store/cnpzq6z5xjxzxw2m3d1cfb5yhpazscn5-python2.7-rhodecode-enterprise-ce-4.22.0/lib/python2.7/site-packages/rhodecode/model/db.py", line 927, in get_by_username
return q.scalar()
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 3391, in scalar
ret = self.one()
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 3358, in one
ret = self.one_or_none()
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 3327, in one_or_none
ret = list(self)
  File "/opt/rhodecode/store/cnpzq6z5xjxzxw2m3d1cfb5yhpazscn5-python2.7-rhodecode-enterprise-ce-4.22.0/lib/python2.7/site-packages/rhodecode/lib/caching_query.py", line 93, in __iter__
return super_.__iter__()
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 3402, in __iter__
self.session._autoflush()
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 1602, in _autoflush
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 1591, in _autoflush
self.flush()
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 2496, in flush
self._flush(objects)
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 2637, in _flush
transaction.rollback(_capture_exception=True)
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/util/langhelpers.py", line 69, in __exit__
exc_value, with_traceback=exc_tb,
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 2597, in _flush
flush_context.execute()
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 422, in execute
rec.execute(self)
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 589, in execute
uow,
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 245, in save_obj
insert,
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 1136, in _emit_insert_statements
statement, params
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 984, in execute
return meth(self, multiparams, params)
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/sql/elements.py", line 293, in _execute_on_connection
return connection._execute_clauseelement(self, multiparams, params)
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1103, in _execute_clauseelement
distilled_params,
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1288, in _execute_context
e, statement, parameters, cursor, context
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1482, in _handle_dbapi_exception
sqlalchemy_exception, with_traceback=exc_info[2], from_=e
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1248, in _execute_context
cursor, statement, parameters, context
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 588, in do_execute
cursor.execute(statement, parameters)
IntegrityError: (raised as a result of Query-invoked autoflush; consider using a session.no_autoflush block if this flush is occurring prematurely)
(pysqlite2.dbapi2.IntegrityError) UNIQUE constraint failed: repositories.repo_name_hash
[SQL: INSERT INTO repositories (repo_name, repo_name_hash, repo_state, clone_uri, push_uri, repo_type, user_id, private, archived, statistics, downloads, description, created_on, updated_on, landing_revision, enable_locking, locked, changeset_cache, fork_id, group_id) VALUES (?,
 ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)]
[parameters: (u'Test-hg', '103a8582308c9c70b047877ee4365d94232da5f0', 'repo_state_pending', '', None, 'hg', 2, 0, 0, 1, 1, u'Test-hg', '2020-11-30 14:51:54.098538', '2020-11-30 14:51:54.098555', 'branch:default', 0, None, None, None, None)]
(Background on this error at: http://sqlalche.me/e/gkpj)
2020-11-30 14:51:54.245 [2299] WARNI [rhodecode.task.create_repo] Exception occurred when creating repository, doing cleanup...
Traceback (most recent call last):
  File "/opt/rhodecode/store/cnpzq6z5xjxzxw2m3d1cfb5yhpazscn5-python2.7-rhodecode-enterprise-ce-4.22.0/lib/python2.7/site-packages/rhodecode/lib/celerylib/tasks.py", line 191, in create_repo
state=state
  File "/opt/rhodecode/store/cnpzq6z5xjxzxw2m3d1cfb5yhpazscn5-python2.7-rhodecode-enterprise-ce-4.22.0/lib/python2.7/site-packages/rhodecode/model/repo.py", line 582, in _create_repo
perm_obj = self._create_default_perms(new_repo, private)
  File "/opt/rhodecode/store/cnpzq6z5xjxzxw2m3d1cfb5yhpazscn5-python2.7-rhodecode-enterprise-ce-4.22.0/lib/python2.7/site-packages/rhodecode/model/repo.py", line 69, in _create_default_perms
def_user = User.get_default_user()
  File "/opt/rhodecode/store/cnpzq6z5xjxzxw2m3d1cfb5yhpazscn5-python2.7-rhodecode-enterprise-ce-4.22.0/lib/python2.7/site-packages/rhodecode/model/db.py", line 1047, in get_default_user
user = User.get_by_username(User.DEFAULT_USER, cache=cache)
  File "/opt/rhodecode/store/cnpzq6z5xjxzxw2m3d1cfb5yhpazscn5-python2.7-rhodecode-enterprise-ce-4.22.0/lib/python2.7/site-packages/rhodecode/model/db.py", line 927, in get_by_username
return q.scalar()
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 3391, in scalar
ret = self.one()
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 3358, in one
ret = self.one_or_none()
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 3327, in one_or_none
ret = list(self)
  File "/opt/rhodecode/store/cnpzq6z5xjxzxw2m3d1cfb5yhpazscn5-python2.7-rhodecode-enterprise-ce-4.22.0/lib/python2.7/site-packages/rhodecode/lib/caching_query.py", line 93, in __iter__
return super_.__iter__()
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 3402, in __iter__
self.session._autoflush()
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 1602, in _autoflush
util.raise_(e, with_traceback=sys.exc_info()[2])
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 1591, in _autoflush
self.flush()
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 2496, in flush
self._flush(objects)
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 2637, in _flush
transaction.rollback(_capture_exception=True)
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/util/langhelpers.py", line 69, in __exit__
exc_value, with_traceback=exc_tb,
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 2597, in _flush
flush_context.execute()
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 422, in execute
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 589, in execute
uow,
 File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 245, in save_obj
insert,
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 1136, in _emit_insert_statements
statement, params
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 984, in execute
return meth(self, multiparams, params)
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/sql/elements.py", line 293, in _execute_on_connection
return connection._execute_clauseelement(self, multiparams, params)
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1103, in _execute_clauseelement
distilled_params,
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1288, in _execute_context
e, statement, parameters, cursor, context
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1482, in _handle_dbapi_exception
sqlalchemy_exception, with_traceback=exc_info[2], from_=e
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1248, in _execute_context
cursor, statement, parameters, context
  File "/opt/rhodecode/store/d9q26gqyfrarins50zxxq1c611alijr2-python2.7-sqlalchemy-1.3.15/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 588, in do_execute
cursor.execute(statement, parameters)
IntegrityError: (raised as a result of Query-invoked autoflush; consider using a session.no_autoflush block if this flush is occurring prematurely)
 (pysqlite2.dbapi2.IntegrityError) UNIQUE constraint failed: repositories.repo_name_hash
 [SQL: INSERT INTO repositories (repo_name, repo_name_hash, repo_state, clone_uri, push_uri, repo_type, user_id, private, archived, statistics, downloads, description, created_on, updated_on, landing_revision, enable_locking, locked, changeset_cache, fork_id, group_id) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)]
 [parameters: (u'Test-hg', '103a8582308c9c70b047877ee4365d94232da5f0', 'repo_state_pending', '', None, 'hg', 2, 0, 0, 1, 1, u'Test-hg', '2020-11-30 14:51:54.098538', '2020-11-30 14:51:54.098555', 'branch:default', 0, None, None, None, None)]
(Background on this error at: http://sqlalche.me/e/gkpj)

The second thing that puzzles me in this log is this:

rhodecode-enterprise-ce-4.22.0

In various loglines, while I have recently updated to the latest version (web interface also shows 4.23.1):

RHODECODE CONTROL VERSION: 1.24.2

 - NAME: community-2
 - STATUS: RUNNING
   logs: /home/rhodecode/.rccontrol/community-2/community.log
 - VERSION: 4.23.1 Community
 - VCS: vcsserver-2
 - URL: http://127.0.0.1:8060
 - CONFIG: /home/rhodecode/.rccontrol/community-2/rhodecode.ini

 - NAME: vcsserver-2
 - STATUS: RUNNING
   logs: /home/rhodecode/.rccontrol/vcsserver-2/vcsserver.log
 - VERSION: 4.23.1 VCSServer
 - URL: http://127.0.0.1:10011
 - CONFIG: /home/rhodecode/.rccontrol/vcsserver-2/vcsserver.ini

After navigating back to ‘home’ the new repo does not show but when I run remap/rescan:

The repository is actually created, only the user interface update failed initially!

Looking at the layer beneath Celery: Redis seems to work fine, I am using it for the beaker session stuff:

beaker.session.type = ext:redis
beaker.session.url = localhost:6379

Works fine and see no errors in the redis log file.

So I am at a loss how this happens. Turning off celery kind of fixes it for me but that is not nice with big repository forks as jobs are not queued.

Best Regards,

Frits

rhodecode-support · November 30, 2020, 4:00pm

We’re not sure about this one, potentially some artifacts for migration. The loop in creation screen means the workers never pick the repository creation task, thus it never completes.

Config was using an older DB potentially? Please try to restart your entire rhodecode by doing rccontrol self-stop && rccontrol self-init ?

holstf · December 1, 2020, 10:42pm

(Sorry for the slow answer, I had to wait till after office hours since UAT testing was in progress)

Yes, that did the trick. Ran these commands, enabled celery in rhodecode.ini and restarted vcsserver and community server.
Repo creation with progress bar updates after a few seconds and lands on the overview page of the just created.

What do these commands do? The documentation is a bit minimal on this.
Am I guessing right that this forces the rccontrol to rescan all packages or so?

Thanks,

Frits.

rhodecode-support · December 2, 2020, 6:43am

These commands restarts also the supervisord, which is a service manager for rhodecode, it basically means it’s a “reboot” kind of restart of rhodecode. Supervisord also runs celery workers, so this “reboot” made them actually start-up because there was a new entry created using rccontrol enable-module celery.

holstf · December 2, 2020, 3:16pm

It is maybe a good idea to add this as a tip to the sqlite to pgsql migration procedure article?
I am pretty sure these Celery troubles started for me after the migration procedure. (had celery/redis running really fine before I migrated the database).