Weblate: Celery systemd silent 'crash'

[derN3rd]

Hey there,

I upgraded to weblate 3.3 (step by step from 2.19.1) and everything worked fine. Except the celery worker.
Im running Weblate in a virtualenv in /home/ubuntu/weblateenv/ with python2.7 with uwsgi.
It has been always a pain with file/dir permissions and I think it might have to do something with it.

I added the config files from the example folder to add a new systemd service for celery and configured it to run as www-data (because uwsgi runs as www-data as well).
When I look at the log files from celery (and also when I run i manually), I noticed that celery it shutting down after a few seconds or when i open the Perfomance report in the weblate admin panel.

celery logs are attached below

To Reproduce
Steps to reproduce the behavior:

1. start celery worker(s) with sudo systemctl start celery-weblate.service
2. wait a few minutes or open the "Performance report" in wl admin panel
3. Celery will shutdown
4. logs don't show any error

Expected behavior
Celery should not be 'crashing'

Server configuration and status

Output of celery log

[2018-12-01 10:39:18,224: INFO/Beat] beat: Starting...
[2018-12-01 10:39:18,236: DEBUG/Beat] Current schedule:
<ScheduleEntry: configuration-health-check weblate.wladmin.tasks.configuration_health_check() <freq: 1.00 hour>
<ScheduleEntry: screenshot-files-cleanup weblate.screenshots.tasks.cleanup_screenshot_files() <freq: 1.00 day>
<ScheduleEntry: cleanup-stale-repos weblate.trans.tasks.cleanup_stale_repos() <freq: 1.00 day>
<ScheduleEntry: fulltext-cleanup weblate.trans.tasks.cleanup_fulltext() <crontab: 30 2 saturday * * (m/h/d/dM/MY)>
<ScheduleEntry: translation-memory-optimize weblate.memory.tasks.memory_optimize() <freq: 7.00 days>
<ScheduleEntry: commit-pending weblate.trans.tasks.commit_pending() <freq: 1.00 hour>
<ScheduleEntry: social-auth-cleanup weblate.accounts.tasks.cleanup_social_auth() <freq: 1.00 hour>
<ScheduleEntry: fulltext-optimize weblate.trans.tasks.optimize_fulltext() <crontab: 30 2 sunday * * (m/h/d/dM/MY)>
<ScheduleEntry: repository-alerts weblate.trans.tasks.repository_alerts() <freq: 1.00 day>
<ScheduleEntry: update-remotes weblate.trans.tasks.update_remotes() <crontab: 30 3 * * * (m/h/d/dM/MY)>
<ScheduleEntry: suggestions-cleanup weblate.trans.tasks.cleanup_suggestions() <freq: 1.00 day>
<ScheduleEntry: cleanup-old-suggestions weblate.trans.tasks.cleanup_old_suggestions() <freq: 1.00 day>
<ScheduleEntry: translation-memory-backup weblate.memory.tasks.memory_backup() <freq: 1.00 day>
[2018-12-01 10:39:18,237: DEBUG/Beat] beat: Ticking with max interval->5.00 minutes
[2018-12-01 10:39:18,238: DEBUG/Beat] beat: Waking up in 5.00 minutes.
[2018-12-01 10:39:18,360: INFO/MainProcess] Connected to redis://localhost:6379//
[2018-12-01 10:39:18,366: INFO/MainProcess] mingle: searching for neighbors
[2018-12-01 10:39:19,379: INFO/MainProcess] mingle: all alone
[2018-12-01 10:39:28,227: DEBUG/MainProcess] Canceling task consumer...
[2018-12-01 10:39:29,234: INFO/MainProcess] beat: Shutting down...
[2018-12-01 10:39:29,234: DEBUG/MainProcess] Canceling task consumer...
[2018-12-01 10:39:29,234: DEBUG/MainProcess] Closing consumer channel...
[2018-12-01 10:39:29,236: DEBUG/MainProcess] removing tasks from inqueue until task handler finished

Output of list_versions

www-data@ip-of-server:~$ /home/ubuntu/weblateenv/bin/weblate list_versions
 * Weblate 3.3
 * Python 2.7.12
 * Django 1.11.11
 * 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.7.4
 * Pillow 5.0.0
 * python-dateutil 2.7.1
 * lxml 4.2.1
 * django-crispy-forms 1.7.2
 * django_compressor 2.2
 * djangorestframework 3.9.0
 * user-agents 1.1.0
 * jellyfish 0.6.1
 * pytz 2018.3
 * pyuca 1.2
 * python-bidi 0.4.0
 * PyYAML 3.12
 * Database backends: django.db.backends.mysql
 * Cache backends: default:MemcachedCache, avatar:FileBasedCache
 * Celery: redis://localhost:6379/0, redis://localhost:6379/0, regular
 * Platform: Linux 4.4.0-1049-aws (x86_64)

Output of check --deploy

www-data@ip-of-server:~$ /home/ubuntu/weblateenv/bin/weblate check --deploy
SystemCheckError: System check identified some issues:

CRITICALS:
?: (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

WARNINGS:
?: (security.W005) You have not set the SECURE_HSTS_INCLUDE_SUBDOMAINS setting to True. Without this, your site is potentially vulnerable to attack via an insecure connection to a subdomain. Only set this to True if you are certain that all subdomains of your domain should be served exclusively via SSL.
?: (security.W021) You have not set the SECURE_HSTS_PRELOAD setting to True. Without this, your site cannot be submitted to the browser preload list.

System check identified 3 issues (0 silenced).

.

Additional context
redis-server is installed as default, untouched config.

additional celery log when I run it manually as www-data

www-data@ip-of-server:~$ /home/ubuntu/weblateenv/bin/celery worker --app weblate --loglevel debug --beat -E

 -------------- celery@ip-of-server v4.2.1 (windowlicker)
---- **** ----- 
--- * ***  * -- Linux-4.4.0-1049-aws-x86_64-with-Ubuntu-16.04-xenial 2018-12-01 11:14:37
-- * - **** --- 
- ** ---------- [config]
- ** ---------- .> app:         weblate:0x7f046705ca90
- ** ---------- .> transport:   redis://localhost:6379/0
- ** ---------- .> results:     redis://localhost:6379/0
- *** --- * --- .> concurrency: 2 (prefork)
-- ******* ---- .> task events: ON
--- ***** ----- 
 -------------- [queues]
                .> celery           exchange=celery(direct) key=celery


[tasks]
  . celery.accumulate
  . celery.backend_cleanup
  . celery.chain
  . celery.chord
  . celery.chord_unlock
  . celery.chunks
  . celery.group
  . celery.map
  . celery.starmap
  . weblate.accounts.notifications.send_mails
  . weblate.accounts.tasks.cleanup_social_auth
  . weblate.memory.tasks.import_memory
  . weblate.memory.tasks.memory_backup
  . weblate.memory.tasks.memory_optimize
  . weblate.memory.tasks.update_memory_task
  . weblate.screenshots.tasks.cleanup_screenshot_files
  . weblate.trans.discovery.create_component
  . weblate.trans.models.update_checks
  . weblate.trans.search.delete_fulltext
  . weblate.trans.search.update_fulltext
  . weblate.trans.tasks.cleanup_fulltext
  . weblate.trans.tasks.cleanup_old_suggestions
  . weblate.trans.tasks.cleanup_project
  . weblate.trans.tasks.cleanup_stale_repos
  . weblate.trans.tasks.cleanup_suggestions
  . weblate.trans.tasks.commit_pending
  . weblate.trans.tasks.optimize_fulltext
  . weblate.trans.tasks.perform_commit
  . weblate.trans.tasks.perform_load
  . weblate.trans.tasks.perform_push
  . weblate.trans.tasks.perform_update
  . weblate.trans.tasks.repository_alerts
  . weblate.trans.tasks.update_remotes
  . weblate.utils.tasks.ping
  . weblate.wladmin.tasks.configuration_health_check

[2018-12-01 11:14:37,269: INFO/Beat] beat: Starting...
[2018-12-01 11:14:37,281: DEBUG/Beat] Current schedule:
<ScheduleEntry: configuration-health-check weblate.wladmin.tasks.configuration_health_check() <freq: 1.00 hour>
<ScheduleEntry: screenshot-files-cleanup weblate.screenshots.tasks.cleanup_screenshot_files() <freq: 1.00 day>
<ScheduleEntry: translation-memory-backup weblate.memory.tasks.memory_backup() <freq: 1.00 day>
<ScheduleEntry: fulltext-cleanup weblate.trans.tasks.cleanup_fulltext() <crontab: 30 2 saturday * * (m/h/d/dM/MY)>
<ScheduleEntry: translation-memory-optimize weblate.memory.tasks.memory_optimize() <freq: 7.00 days>
<ScheduleEntry: commit-pending weblate.trans.tasks.commit_pending() <freq: 1.00 hour>
<ScheduleEntry: social-auth-cleanup weblate.accounts.tasks.cleanup_social_auth() <freq: 1.00 hour>
<ScheduleEntry: cleanup-old-suggestions weblate.trans.tasks.cleanup_old_suggestions() <freq: 1.00 day>
<ScheduleEntry: repository-alerts weblate.trans.tasks.repository_alerts() <freq: 1.00 day>
<ScheduleEntry: suggestions-cleanup weblate.trans.tasks.cleanup_suggestions() <freq: 1.00 day>
<ScheduleEntry: update-remotes weblate.trans.tasks.update_remotes() <crontab: 30 3 * * * (m/h/d/dM/MY)>
<ScheduleEntry: fulltext-optimize weblate.trans.tasks.optimize_fulltext() <crontab: 30 2 sunday * * (m/h/d/dM/MY)>
<ScheduleEntry: cleanup-stale-repos weblate.trans.tasks.cleanup_stale_repos() <freq: 1.00 day>
[2018-12-01 11:14:37,282: DEBUG/Beat] beat: Ticking with max interval->5.00 minutes
[2018-12-01 11:14:37,284: DEBUG/Beat] beat: Waking up in 5.00 minutes.
[2018-12-01 11:14:37,405: INFO/MainProcess] Connected to redis://localhost:6379/0
[2018-12-01 11:14:37,411: INFO/MainProcess] mingle: searching for neighbors
[2018-12-01 11:14:38,424: INFO/MainProcess] mingle: all alone
[2018-12-01 11:14:38,632: DEBUG/MainProcess] Canceling task consumer...
[2018-12-01 11:14:39,638: INFO/MainProcess] beat: Shutting down...
[2018-12-01 11:14:39,638: DEBUG/MainProcess] Canceling task consumer...
[2018-12-01 11:14:39,638: DEBUG/MainProcess] Closing consumer channel...
[2018-12-01 11:14:39,639: DEBUG/MainProcess] removing tasks from inqueue until task handler finished

[nijel]

Looks like Celery 4 is having such issues in some cases, for example see https://github.com/celery/celery/issues/5013. I haven't seen this yet personally...

[derN3rd]

Downgrading to celery 4.1.1 as they said in celery/celery#5013 didn't change anything.
Waiting for new ideas.

[nijel]

It could be useful to know why the shutdown was initiated. If you can use some Python debugger setting breakpoint on celery/consumer/tasks.py:54 could help.

Alternatively raising exception there could reveal the backtrace (though I'm not sure if Celery won't hide that away):

diff --git a/celery/worker/consumer/tasks.py b/celery/worker/consumer/tasks.py
index 030a20091..fdc2301c2 100644
--- a/celery/worker/consumer/tasks.py
+++ b/celery/worker/consumer/tasks.py
@@ -50,6 +50,7 @@ class Tasks(bootsteps.StartStopStep):

     def stop(self, c):
         """Stop task consumer."""
+        raise Exception('debug')
         if c.task_consumer:
             debug('Canceling task consumer...')
             ignore_errors(c, c.task_consumer.cancel)

[derN3rd]

After patching tasks.py
I run celery worker --app weblate --loglevel debug --beat -E with www-user again and reload the /admin/performance/ url to see if it keeps crashing the celery worker.
I get the following output:

Toggle output

www-data@ip-of-server:~$ /home/ubuntu/weblateenv/bin/celery worker --app weblate --loglevel debug --beat -E

 -------------- celery@ip-of-server v4.1.1 (latentcall)
---- **** ----- 
--- * ***  * -- Linux-4.4.0-1049-aws-x86_64-with-Ubuntu-16.04-xenial 2018-12-01 12:58:49
-- * - **** --- 
- ** ---------- [config]
- ** ---------- .> app:         weblate:0x7f7c7f419090
- ** ---------- .> transport:   redis://127.0.0.1:6379/0
- ** ---------- .> results:     redis://127.0.0.1:6379/0
- *** --- * --- .> concurrency: 2 (prefork)
-- ******* ---- .> task events: ON
--- ***** ----- 
 -------------- [queues]
                .> celery           exchange=celery(direct) key=celery


[tasks]
  . celery.accumulate
  . celery.backend_cleanup
  . celery.chain
  . celery.chord
  . celery.chord_unlock
  . celery.chunks
  . celery.group
  . celery.map
  . celery.starmap
  . weblate.accounts.notifications.send_mails
  . weblate.accounts.tasks.cleanup_social_auth
  . weblate.memory.tasks.import_memory
  . weblate.memory.tasks.memory_backup
  . weblate.memory.tasks.memory_optimize
  . weblate.memory.tasks.update_memory_task
  . weblate.screenshots.tasks.cleanup_screenshot_files
  . weblate.trans.discovery.create_component
  . weblate.trans.models.update_checks
  . weblate.trans.search.delete_fulltext
  . weblate.trans.search.update_fulltext
  . weblate.trans.tasks.cleanup_fulltext
  . weblate.trans.tasks.cleanup_old_suggestions
  . weblate.trans.tasks.cleanup_project
  . weblate.trans.tasks.cleanup_stale_repos
  . weblate.trans.tasks.cleanup_suggestions
  . weblate.trans.tasks.commit_pending
  . weblate.trans.tasks.optimize_fulltext
  . weblate.trans.tasks.perform_commit
  . weblate.trans.tasks.perform_load
  . weblate.trans.tasks.perform_push
  . weblate.trans.tasks.perform_update
  . weblate.trans.tasks.repository_alerts
  . weblate.trans.tasks.update_remotes
  . weblate.utils.tasks.ping
  . weblate.wladmin.tasks.configuration_health_check

[2018-12-01 12:58:49,164: INFO/Beat] beat: Starting...
[2018-12-01 12:58:49,176: DEBUG/Beat] Current schedule:
<ScheduleEntry: configuration-health-check weblate.wladmin.tasks.configuration_health_check() <freq: 1.00 hour>
<ScheduleEntry: screenshot-files-cleanup weblate.screenshots.tasks.cleanup_screenshot_files() <freq: 1.00 day>
<ScheduleEntry: cleanup-stale-repos weblate.trans.tasks.cleanup_stale_repos() <freq: 1.00 day>
<ScheduleEntry: fulltext-cleanup weblate.trans.tasks.cleanup_fulltext() <crontab: 30 2 saturday * * (m/h/d/dM/MY)>
<ScheduleEntry: translation-memory-optimize weblate.memory.tasks.memory_optimize() <freq: 7.00 days>
<ScheduleEntry: commit-pending weblate.trans.tasks.commit_pending() <freq: 1.00 hour>
<ScheduleEntry: social-auth-cleanup weblate.accounts.tasks.cleanup_social_auth() <freq: 1.00 hour>
<ScheduleEntry: fulltext-optimize weblate.trans.tasks.optimize_fulltext() <crontab: 30 2 sunday * * (m/h/d/dM/MY)>
<ScheduleEntry: repository-alerts weblate.trans.tasks.repository_alerts() <freq: 1.00 day>
<ScheduleEntry: update-remotes weblate.trans.tasks.update_remotes() <crontab: 30 3 * * * (m/h/d/dM/MY)>
<ScheduleEntry: suggestions-cleanup weblate.trans.tasks.cleanup_suggestions() <freq: 1.00 day>
<ScheduleEntry: cleanup-old-suggestions weblate.trans.tasks.cleanup_old_suggestions() <freq: 1.00 day>
<ScheduleEntry: translation-memory-backup weblate.memory.tasks.memory_backup() <freq: 1.00 day>
[2018-12-01 12:58:49,177: DEBUG/Beat] beat: Ticking with max interval->5.00 minutes
[2018-12-01 12:58:49,179: DEBUG/Beat] beat: Waking up in 5.00 minutes.
[2018-12-01 12:58:49,300: INFO/MainProcess] Connected to redis://127.0.0.1:6379/0
[2018-12-01 12:58:49,307: INFO/MainProcess] mingle: searching for neighbors
[2018-12-01 12:58:50,320: INFO/MainProcess] mingle: all alone
[2018-12-01 12:58:59,159: INFO/MainProcess] beat: Shutting down...
[2018-12-01 12:58:59,442: DEBUG/MainProcess] Sending message of length 5614 to https://sentry.io/api/627997/store/
[2018-12-01 12:58:59,442: WARNING/MainProcess] Traceback (most recent call last):
[2018-12-01 12:58:59,443: WARNING/MainProcess] File "/home/ubuntu/weblateenv/bin/celery", line 11, in <module>
[2018-12-01 12:58:59,443: WARNING/MainProcess] sys.exit(main())
[2018-12-01 12:58:59,444: WARNING/MainProcess] File "/home/ubuntu/weblateenv/local/lib/python2.7/site-packages/celery/__main__.py", line 16, in main
[2018-12-01 12:58:59,444: WARNING/MainProcess] _main()
[2018-12-01 12:58:59,444: WARNING/MainProcess] File "/home/ubuntu/weblateenv/local/lib/python2.7/site-packages/celery/bin/celery.py", line 322, in main
[2018-12-01 12:58:59,445: WARNING/MainProcess] cmd.execute_from_commandline(argv)
[2018-12-01 12:58:59,445: WARNING/MainProcess] File "/home/ubuntu/weblateenv/local/lib/python2.7/site-packages/celery/bin/celery.py", line 484, in execute_from_commandline
[2018-12-01 12:58:59,445: WARNING/MainProcess] super(CeleryCommand, self).execute_from_commandline(argv)))
[2018-12-01 12:58:59,445: WARNING/MainProcess] File "/home/ubuntu/weblateenv/local/lib/python2.7/site-packages/celery/bin/base.py", line 275, in execute_from_commandline
[2018-12-01 12:58:59,445: WARNING/MainProcess] return self.handle_argv(self.prog_name, argv[1:])
[2018-12-01 12:58:59,445: WARNING/MainProcess] File "/home/ubuntu/weblateenv/local/lib/python2.7/site-packages/celery/bin/celery.py", line 476, in handle_argv
[2018-12-01 12:58:59,446: WARNING/MainProcess] return self.execute(command, argv)
[2018-12-01 12:58:59,446: WARNING/MainProcess] File "/home/ubuntu/weblateenv/local/lib/python2.7/site-packages/celery/bin/celery.py", line 408, in execute
[2018-12-01 12:58:59,446: WARNING/MainProcess] ).run_from_argv(self.prog_name, argv[1:], command=argv[0])
[2018-12-01 12:58:59,446: WARNING/MainProcess] File "/home/ubuntu/weblateenv/local/lib/python2.7/site-packages/celery/bin/worker.py", line 223, in run_from_argv
[2018-12-01 12:58:59,446: WARNING/MainProcess] return self(*args, **options)
[2018-12-01 12:58:59,446: WARNING/MainProcess] File "/home/ubuntu/weblateenv/local/lib/python2.7/site-packages/celery/bin/base.py", line 238, in __call__
[2018-12-01 12:58:59,447: WARNING/MainProcess] ret = self.run(*args, **kwargs)
[2018-12-01 12:58:59,447: WARNING/MainProcess] File "/home/ubuntu/weblateenv/local/lib/python2.7/site-packages/celery/bin/worker.py", line 258, in run
[2018-12-01 12:58:59,447: WARNING/MainProcess] worker.start()
[2018-12-01 12:58:59,447: WARNING/MainProcess] File "/home/ubuntu/weblateenv/local/lib/python2.7/site-packages/celery/worker/worker.py", line 210, in start
[2018-12-01 12:58:59,447: WARNING/MainProcess] self.stop(exitcode=EX_FAILURE)
[2018-12-01 12:58:59,447: WARNING/MainProcess] File "/home/ubuntu/weblateenv/local/lib/python2.7/site-packages/celery/worker/worker.py", line 253, in stop
[2018-12-01 12:58:59,448: WARNING/MainProcess] self._shutdown(warm=True)
[2018-12-01 12:58:59,448: WARNING/MainProcess] File "/home/ubuntu/weblateenv/local/lib/python2.7/site-packages/celery/worker/worker.py", line 268, in _shutdown
[2018-12-01 12:58:59,448: WARNING/MainProcess] self.blueprint.stop(self, terminate=not warm)
[2018-12-01 12:58:59,448: WARNING/MainProcess] File "/home/ubuntu/weblateenv/local/lib/python2.7/site-packages/celery/bootsteps.py", line 177, in stop
[2018-12-01 12:58:59,448: WARNING/MainProcess] self.on_stopped()
[2018-12-01 12:58:59,448: WARNING/MainProcess] File "/home/ubuntu/weblateenv/local/lib/python2.7/site-packages/celery/worker/worker.py", line 164, in on_stopped
[2018-12-01 12:58:59,448: WARNING/MainProcess] self.consumer.shutdown()
[2018-12-01 12:58:59,449: WARNING/MainProcess] File "/home/ubuntu/weblateenv/local/lib/python2.7/site-packages/celery/worker/consumer/consumer.py", line 351, in shutdown
[2018-12-01 12:58:59,449: WARNING/MainProcess] self.blueprint.shutdown(self)
[2018-12-01 12:58:59,449: WARNING/MainProcess] File "/home/ubuntu/weblateenv/local/lib/python2.7/site-packages/celery/worker/consumer/consumer.py", line 159, in shutdown
[2018-12-01 12:58:59,449: WARNING/MainProcess] self.send_all(parent, 'shutdown')
[2018-12-01 12:58:59,449: WARNING/MainProcess] File "/home/ubuntu/weblateenv/local/lib/python2.7/site-packages/celery/bootsteps.py", line 151, in send_all
[2018-12-01 12:58:59,449: WARNING/MainProcess] fun(parent, *args)
[2018-12-01 12:58:59,449: WARNING/MainProcess] File "/home/ubuntu/weblateenv/local/lib/python2.7/site-packages/celery/worker/consumer/tasks.py", line 60, in shutdown
[2018-12-01 12:58:59,449: WARNING/MainProcess] self.stop(c)
[2018-12-01 12:58:59,450: WARNING/MainProcess] File "/home/ubuntu/weblateenv/local/lib/python2.7/site-packages/celery/worker/consumer/tasks.py", line 52, in stop
[2018-12-01 12:58:59,450: WARNING/MainProcess] raise Exception('debug')
[2018-12-01 12:58:59,450: WARNING/MainProcess] Exception
[2018-12-01 12:58:59,450: WARNING/MainProcess] :
[2018-12-01 12:58:59,450: WARNING/MainProcess] debug
[2018-12-01 12:58:59,550: WARNING/MainProcess] Sentry is attempting to send 1 pending error messages
[2018-12-01 12:58:59,551: WARNING/MainProcess] Waiting up to 10 seconds
[2018-12-01 12:58:59,551: WARNING/MainProcess] Press Ctrl-C to quit
[2018-12-01 12:58:59,966: DEBUG/MainProcess] removing tasks from inqueue until task handler finished

EDIT: more detailed sentry link https://sentry.io/share/issue/12cfc47576954e1bb793872526f46e09/

[nijel]

Okay, apparently there is some error going on (see celery/worker/worker.py in start at line 210), but for some reason the critical log is not shown for some reason. Do you happen to have the exc variable stored in Sentry (it's not shown in the shared link, but I think it Sentry hiding variables by default in this case)? If not adding print there could help to figure out what is going wrong.

Anyway this should be in the worker logs, I have no clue why it's not shown if you start it in the foreground. For the daemon mode, these end up in separate files, so maybe checking those could help.

[derN3rd]

The breadcrumbs did some help:

[nijel]

Ah, that one seems to be known bug with known fix: https://github.com/celery/celery/issues/5175#issuecomment-439073455

[derN3rd]

Finally, it works! @nijel you are my hero :smile:

[nijel]

Great :-)

[nijel]

In case somebody else runs into this as well, adding actual error messages as text to help searching (two variants depending on Python version):

 AttributeError: 'float' object has no attribute 'items'
 AttributeError: 'float' object has no attribute 'iteritems'