GitHub webhook sometimes does not take proper action

[stanislav-brabec]

Describe the bug
I get repeated conflicts in the yast repository in the openSUSE Weblate:
https://l10n.opensuse.org/projects/yast-base/master/

Attempting to track this issue, I see that some GitHub webhooks are silently ignored.

The problem is not easily reproducible. Some hooks are correctly processed but some are ignored.

Note that yast-base project is heavily linked. It is used as a weblate internal link by more than 100 components.

To Reproduce
Steps to reproduce the behavior:

1. Properly configure hook system.
2. Unknown condition

GitHub shows:
2019-03-13 21:59:56
Response 200
Completed in 2.03 seconds.

Weblate log shows:
Mar 13 20:59:58 nuka weblate[2198]: INFO received GitHub notification on repository https://github.com/yast/yast-translations, branch master, 1 matching components, 1 to process
Mar 13 20:59:58 nuka uwsgi[2159]: INFO:weblate:received GitHub notification on repository https://github.com/yast/yast-translations, branch master, 1 matching components, 1 to process
Mar 13 20:59:58 nuka weblate[2198]: INFO GitHub notification will update yast-base/master
Mar 13 20:59:58 nuka uwsgi[2159]: INFO:weblate:GitHub notification will update yast-base/master
Mar 13 20:59:58 nuka uwsgi[2159]: [pid: 2198|app: 0|req: 183411/1821955] 192.168.47.102 () {54 vars in 799 bytes} [Wed Mar 13 20:59:58 2019] POST /hooks/github/ => generated 70 bytes in 59 msecs (HTTP/1.1 200) 9 headers in 494 bytes (1 switches on core 0)

But 15 minutes later, yast-base information still shows outdated GitHub commit.

Trying GitHub redelived the hook, nothing changes, pull is not called.

Manual pressing of Pull button in the Repository Maintenance works.

Expected behavior
Ignore no webhooks.

Screenshots
If applicable, add screenshots to help explain your problem.

Server configuration and status

./manage.py list_versions
 * Weblate 3.3
 * Python 3.6.5
 * Django 2.0.8
 * Celery 4.2.1
 * celery-batches 0.2
 * six 1.11.0
 * social-auth-core 2.0.0
 * social-auth-app-django 3.1.0
 * django-appconf 1.0.2
 * translate-toolkit 2.3.1
 * Whoosh 2.7.4
 * defusedxml 0.5.0
 * Git 2.16.4
 * Pillow 5.0.0
 * python-dateutil 2.6.1
 * lxml 4.0.0
 * django-crispy-forms 1.7.2
 * django_compressor 2.2
 * djangorestframework 3.9.0
 * user-agents 1.1.0
 * jellyfish 0.6.1
 * pytz 2017.3
 * pyuca 1.2
 * PyYAML 3.12
 * Database backends: django.db.backends.postgresql_psycopg2
 * Cache backends: default:RedisCache, avatar:FileBasedCache
 * Celery: redis://localhost:6379, redis://localhost:6379, regular
 * Platform: Linux 4.12.14-lp150.12.45-default (x86_64)
./manage.py check --deploy
SystemCheckError: System check identified some issues:

CRITICALS:
?: (weblate.E009) The Celery tasks queue is too long, either the worker is not running or is too slow.
	HINT: https://docs.weblate.org/en/weblate-3.3/admin/install.html#celery
?: (weblate.E019) The Celery does not process tasks or is too slow in processing them.
	HINT: https://docs.weblate.org/en/weblate-3.3/admin/install.html#celery

System check identified 2 issues (0 silenced).

Note: Celery is properly installed.

Last items celery logs:

/var/log/celery/weblate-celery.log:
[2019-03-13 19:31:49,021: INFO/MainProcess] Received task: weblate.trans.tasks.perform_update[8e9cf84f-c2c4-464d-924d-d5be6d906d74]  

/var/log/celery/weblate-celery-1.log:
[2019-03-12 15:26:53,355: INFO/PoolWorker-2] libstorage-ng/master: running batch check: inconsistent
[2019-03-12 15:26:54,113: INFO/PoolWorker-2] libstorage-ng/master: updating completed

/var/log/celery/weblate-celery-2.log, maybe related:
[2019-03-13 19:59:50,461: INFO/PoolWorker-3] yast-base/master: running batch check: inconsistent
... here is a report about sending mails ...
[2019-03-13 19:59:52,124: INFO/PoolWorker-3] yast-base/master: updating completed

[nijel]

Maybe Celery isn't able to process the tasks in timely manner? Because uwsgi just receives the update (what seems to work fine, there is matched component) and Celery then performs the actual update. The log which you posted is before the event, so it's probably from previous update.

What might help you is to switch to Celery setup introduced in 3.4 where there are multiple queues used. This heavily improves utilization of processes as they no longer fight for memory or fulltext locks. That's just configuration change which is easy to apply to 3.3:

weblate/examples/celery-weblate.conf

Line 13 in 3cb99be

CELERYD_OPTS="--beat:celery --concurrency:celery=4 --queues:celery=celery --prefetch-multiplier:celery=4 --concurrency:search=1 --queues:search=search --prefetch-multiplier:search=2000 --concurrency:memory=1 --queues:memory=memory --prefetch-multiplier:memory=2000"

weblate/weblate/settings_example.py

Lines 841 to 846 in 3cb99be

	CELERY_TASK_ROUTES = {
	'weblate.trans.search.*': {'queue': 'search'},
	'weblate.trans.tasks.optimize_fulltext': {'queue': 'search'},
	'weblate.trans.tasks.cleanup_fulltext': {'queue': 'search'},
	'weblate.memory.tasks.*': {'queue': 'memory'},
	}

[stanislav-brabec]

I plan to upgrade to the new Weblate soon.

It can be the explanation of the problem. yast-translation recently contains 7050 po files, and full processing of changed po files may take ~10 hours. A hour before the problematic commit, a big merge was pushed to GitHub master. It merged about 80 conflicting commits. (Conflicts are regular side effects of delays: Pull that contains pot/po update is delayed, somebody changes po file in Weblate => merge conflicts happens.)

[nijel]

You can also expect processing to take about half time with 3.5.1 (at least that's what benchmark show me in most cases).

[SlavekB]

I don't know if it has any connection with your issue, but I have a significantly larger repository (approx 33700 files po in 563 linked components – files pot), where the po files update took 20 to 40 minutes until I updated from Python 2.7.x to Python 3.5.x – after update, the same task took 10.5 hours! See #2670. Because you mention similarly crazy times with older Weblate, but with Python 3.x, I suspect that the problem is Python 3.x.

[stale]

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.