updategit does nothing

[BhaaLseN]

Describe the bug
The management command updategit doesn't seem to work correctly at this point (no updates happen in the working copy)

To Reproduce
Steps to reproduce the behavior:

1. Prepare a Project/Configuration/Git-Repository (create a new one if necessary)
2. Click on "Manage" > "Repository maintenance" to see the current working copy status; verify it says "The local repository is up to date."
3. Modify a resource file locally, then commit and push it.
4. Run ./manage.py updategit --all
5. Refresh the "Repository maintenance" page; notice it did not update the working copy (no history entry exists)

Expected behavior
The working copy should be updated and translations should synchronize to see the changes on the given component page.

Server configuration and status

$ ./manage.py list_versions
 * Weblate weblate-3.2.2
 * Python 3.5.3
 * Django 2.1.2
 * Celery 4.2.1
 * celery-batches 0.2
 * six 1.11.0
 * social-auth-core 1.7.0
 * social-auth-app-django 2.1.0
 * django-appconf 1.0.2
 * translate-toolkit 2.3.1
 * Whoosh 2.7.4
 * defusedxml 0.5.0
 * Git 2.11.0
 * Pillow 5.3.0
 * python-dateutil 2.7.3
 * lxml 4.2.5
 * 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.5
 * pyuca 1.2
 * python-bidi 0.4.0
 * PyYAML 3.12
 * Database backends: django.db.backends.mysql
 * Cache backends: default:RedisCache
 * Platform: Linux 4.9.0-6-amd64 (x86_64)

$ ./manage.py check --deploy
System check identified some issues:

WARNINGS:
?: (security.W004) You have not set a value for the SECURE_HSTS_SECONDS setting. If your entire site is served only over SSL, you may want to consider setting a value and enabling HTTP Strict Transport Security. Be sure to read the documentation first; enabling HSTS carelessly can cause serious, irreversible problems.

System check identified 1 issue (0 silenced).

Additional context
It took a while for us to notice this, since we had a slow month since the update; as well as some environmental power failures that caused Celery to not work.
But even after restoring, updategit seems to have no effect. commit_pending seems to be a little quirky (which could be #2396) as well.

Both updategit and commit_pending run on an hourly cronjob; mostly because we don't have infrastructure in place (yet) to trigger updates on demand. On that note, using the API operation pull on the repository does update correctly; and we're likely to use that as a workaround in the mean time.

In case it matters, this was a Git update from weblate-3.1.1 to weblate-3.2.2 (to narrow down a range where it could've happened)

[nijel]

The updategit command triggers tasks in Celery, so if that is not working, it's expected to be broken.

[BhaaLseN]

service celery-weblate status shows old messages from commit_git, but nothing from the time I ran updategit at. Edit: To clarify, Celery was not running after a power failure, but is now after fixing it (before I created this issue) - the current problem is not that Celery isn't running, but that tasks being pushed to it don't have any apparent effect.
/var/log/celery/weblate-w1.log has a bunch of task messages, but I'm not sure if that actually does anything:

[2018-11-22 06:55:22,250: INFO/MainProcess] Received task: weblate.trans.tasks.perform_update[11ff3bfe-25a1-4259-b1f2-699e3dd7522f]
[2018-11-22 06:55:22,251: INFO/MainProcess] Received task: weblate.trans.tasks.perform_update[817db927-6107-464e-9d82-8a78d8158696]
[2018-11-22 06:55:22,255: INFO/MainProcess] Received task: weblate.trans.tasks.perform_update[2301c82c-8f46-4932-a73c-b817daa13539]
[2018-11-22 06:55:22,256: INFO/MainProcess] Received task: weblate.trans.tasks.perform_update[e29e5c24-8977-4cc4-9075-dba4a86e6217]
[2018-11-22 06:55:22,257: INFO/MainProcess] Received task: weblate.trans.tasks.perform_update[eefc2ce8-c03d-43ea-bb67-f4c2ebc05f65]
[2018-11-22 06:55:22,259: INFO/MainProcess] Received task: weblate.trans.tasks.perform_update[cb1b3a1f-f102-453d-9b30-99fceade7541]
[2018-11-22 06:55:22,271: INFO/MainProcess] Received task: weblate.trans.tasks.perform_update[3af54737-efb3-467a-9126-25ebf220257d]
[2018-11-22 06:55:22,279: INFO/MainProcess] Received task: weblate.trans.tasks.perform_update[bc143259-4d66-4dba-a93a-f0d7205ffb2d]
[2018-11-22 06:55:22,280: INFO/MainProcess] Received task: weblate.trans.tasks.perform_update[45667601-efa3-48a7-8b52-54dd5aa2ea3e]
[2018-11-22 06:55:22,281: INFO/MainProcess] Received task: weblate.trans.tasks.perform_update[abcae9b1-600a-4a3e-997b-2ff070b12b5f]
[2018-11-22 06:55:22,282: INFO/MainProcess] Received task: weblate.trans.tasks.perform_update[2a139c29-7051-4fd8-9b4b-da30d4755b6f]

It doesn't seem to make a difference either if I use updategit --all, updategit Proj or updategit Proj/Comp.

Also, it seems that using the API /api/projects/Proj/repository does not use Celery to run the update (which seems fair, so it can return a success/error state to the caller). If I POST to the API, Celery receives a weblate.accounts.notifications.send_mails task (possibly because the update in one repository failed due to a merge conflict).

[nblock]

We noticed the same behavior.

The updategit command was invoked as follows (no output):

(venv) $ python manage.py updategit -v 3 PROJECT/COMPONENT

There are some details in celery's log:

[2018-11-22 14:35:09,293: WARNING/MainProcess] Received and deleted unknown message. Wrong destination?!?

The full contents of the message body was: body: [['Component', 38], {}, {'callbacks': None, 'chord': None, 'errbacks': None, 'chain': None}] (92b)
{content_type:'application/json' content_encoding:'utf-8'
  delivery_info:{'routing_key': 'celery', 'exchange': ''} headers={'lang': 'py', 'task': 'weblate.trans.tasks.perform_update', 'group': None, 'shadow': None, 'timelimit': [None, None], 'parent_id': None, 'argsrepr': "('Component', 38)", 'expires': None, 'eta': None, 'root_id': '69b79fb4-8827-4b71-b6c0-54696643d4cd', 'origin': 'gen58424@translate', 'id': '69b79fb4-8827-4b71-b6c0-54696643d4cd', 'retries': 0, 'kwargsrepr': '{}'}}

Pulling the latest updates via Manage -> Repository maintenance -> Pull works as expected.

[BhaaLseN]

Interresting, I don't see those on my end. Just the INFO that the task was received.

[nijel]

@nblock Not sure if your problem is related, that most likely looks like something wrong in your Celery setup - using older protocol might help (see https://stackoverflow.com/a/48648079/225718) or downgrading redis package (see celery/celery#5175).

@BhaaLseN The /var/log/celery/weblate-w1.log log is for the dispatcher only, the individual tasks log into /var/log/celery/weblate-w1-*.log (per worker), so better check these logs for errors.

[nijel]

The log (for DEBUG level) should look like:

[2018-11-23 17:23:14,203: DEBUG/MainProcess] Task accepted: weblate.trans.tasks.perform_update[e226b22f-0d86-401f-9870-cb1b7589ab04] pid:4466
[2018-11-23 17:23:14,206: DEBUG/ForkPoolWorker-2] Attempting to acquire lock 140603400849808 on /home/nijel/weblate/weblate/data/vcs/hello/gettext.lock
[2018-11-23 17:23:14,206: INFO/ForkPoolWorker-2] Lock 140603400849808 acquired on /home/nijel/weblate/weblate/data/vcs/hello/gettext.lock
[2018-11-23 17:23:14,417: DEBUG/ForkPoolWorker-2] weblate: git: git config --replace-all push.default current [retcode=0]
[2018-11-23 17:23:14,418: DEBUG/ForkPoolWorker-2] Attempting to release lock 140603400849808 on /home/nijel/weblate/weblate/data/vcs/hello/gettext.lock
[2018-11-23 17:23:14,419: INFO/ForkPoolWorker-2] Lock 140603400849808 released on /home/nijel/weblate/weblate/data/vcs/hello/gettext.lock
[2018-11-23 17:23:14,419: DEBUG/ForkPoolWorker-2] Attempting to acquire lock 140603400849808 on /home/nijel/weblate/weblate/data/vcs/hello/gettext.lock
[2018-11-23 17:23:14,420: INFO/ForkPoolWorker-2] Lock 140603400849808 acquired on /home/nijel/weblate/weblate/data/vcs/hello/gettext.lock
INFO hello/gettext: updating repository
[2018-11-23 17:23:14,420: INFO/ForkPoolWorker-2] hello/gettext: updating repository
[2018-11-23 17:23:14,421: INFO/ForkPoolWorker-2] Lock 140603400849808 acquired on /home/nijel/weblate/weblate/data/vcs/hello/gettext.lock
[2018-11-23 17:23:14,951: DEBUG/ForkPoolWorker-2] weblate: git: git fetch origin [retcode=0]
INFO hello/gettext: update took 0.53 seconds
[2018-11-23 17:23:14,952: INFO/ForkPoolWorker-2] hello/gettext: update took 0.53 seconds
[2018-11-23 17:23:14,976: DEBUG/ForkPoolWorker-2] weblate: git: git log --format=format:%H ..origin/master -- [retcode=0]
[2018-11-23 17:23:14,976: DEBUG/ForkPoolWorker-2] Attempting to release lock 140603400849808 on /home/nijel/weblate/weblate/data/vcs/hello/gettext.lock
[2018-11-23 17:23:14,976: INFO/ForkPoolWorker-2] Lock 140603400849808 released on /home/nijel/weblate/weblate/data/vcs/hello/gettext.lock
[2018-11-23 17:23:14,977: INFO/ForkPoolWorker-2] Task weblate.trans.tasks.perform_update[e226b22f-0d86-401f-9870-cb1b7589ab04] succeeded in 0.773642363987s: None

[BhaaLseN]

Uh, ok, didn't know they were different. I did see a permission error in there (and fixed it), but I'm not sure if that was the only thing causing problems. I'm on the road atm and don't have full source access, so I won't be able to verify that until monday or so.

I'll leave this open for now if you don't mind; mainly as reminder for myself.

[BhaaLseN]

Alrighty, over night I had another error in the celery worker log:

[2018-11-25 23:05:08,107: ERROR/ForkPoolWorker-2] Error: PermissionError(13, 'Permission denied')
Traceback (most recent call last):
  File "/home/weblate/lib/python3.5/site-packages/celery_batches/__init__.py", line 148, in apply_batches_task
    result = task(*args)
  File "/home/weblate/lib/python3.5/site-packages/celery/app/trace.py", line 642, in __protected_call__
    return orig(self, *args, **kwargs)
  File "/home/weblate/lib/python3.5/site-packages/celery/app/task.py", line 375, in __call__
    return self.run(*args, **kwargs)
  File "/home/weblate/weblate/weblate/trans/search.py", line 286, in delete_fulltext
    fulltext.delete_search_units(units, languages)
  File "/home/weblate/weblate/weblate/trans/search.py", line 249, in delete_search_units
    with index.writer() as writer:
  File "/home/weblate/lib/python3.5/site-packages/whoosh/index.py", line 464, in writer
    return SegmentWriter(self, **kwargs)
  File "/home/weblate/lib/python3.5/site-packages/whoosh/writing.py", line 514, in __init__
    delay=delay):
  File "/home/weblate/lib/python3.5/site-packages/whoosh/util/filelock.py", line 54, in try_for
    v = fn()
  File "/home/weblate/lib/python3.5/site-packages/whoosh/util/filelock.py", line 98, in acquire
    self.fd = os.open(self.filename, flags)
PermissionError: [Errno 13] Permission denied: '/home/weblate/weblate/data/whoosh/target-hu_WRITELOCK'

That WRITELOCK file existed (along with 5 others), it was empty (zero bytes), and the owner was www-data - which probably means that my celery service user had no permission to overwrite it. The most interresting fact though: that file is from March.
Not sure why it was still there.

I removed those files, double-checked permissions (which are now owned by a weblate group that has service users for redis/celery and www-data for the web part in it; with write permissions for the group) and ran updategit again.

After that, all that was left was an SSH authentication issue (caused by the private key having permissions that didn't allow celery to read them; mostly because they were still owned by www-data)

With that, updates now work again. Slightly tedious to debug though, since there is so many places where things can go wrong, and no clear "look at that log file" hint.
Thanks regardless!

[nijel]

This is something Weblate could check automatically and I've implemented the check in e1b0c87. Thank you for your report, the issue you have reported has just been fixed.

• In case you see problem with the fix, please comment on this issue.
• In case you see similar problem, please open separate issue.
• If you are happy with the outcome, consider supporting Weblate by donating.

[nblock]

@nblock Not sure if your problem is related, that most likely looks like something wrong in your Celery setup - using older protocol might help (see https://stackoverflow.com/a/48648079/225718) or downgrading redis package (see celery/celery#5175).

Thanks for your hint. It was a deployment issue. For some reason, I used celeryd from Stretch which is too old and has some issues. Switch to the recommended configuration as per the current documentation and it seems to work fine now.