Card creation failed if content fills the SD card to almost 100%

Popolechien commented 5 years ago

Job L72R5D08 Log (edited because too long for Github):


task path: /var/lib/ansible/local/roles/kalite_content/tasks/main.yml:3
<localhost> ESTABLISH LOCAL CONNECTION FOR USER: root
<localhost> EXEC /bin/sh -c 'echo ~root && sleep 0'
<localhost> EXEC /bin/sh -c '( umask 77 && mkdir -p "` echo /var/tmp/ansible-tmp-1560871710.45-245506636870829 `" && echo ansible-tmp-1560871710.45-245506636870829="` echo /var/tmp/ansible-tmp-1560871710.45-245506636870829 `" ) && sleep 0'
Using module file /usr/local/lib/python2.7/dist-packages/ansible/modules/commands/command.py
<localhost> PUT /root/.ansible/tmp/ansible-local-2345Eavb0w/tmpyVBSPs TO /var/tmp/ansible-tmp-1560871710.45-245506636870829/command.py
<localhost> EXEC /bin/sh -c 'setfacl -m u:ideascube:r-x /var/tmp/ansible-tmp-1560871710.45-245506636870829/ /var/tmp/ansible-tmp-1560871710.45-245506636870829/command.py && sleep 0'
<localhost> EXEC /bin/sh -c 'chmod u+x /var/tmp/ansible-tmp-1560871710.45-245506636870829/ /var/tmp/ansible-tmp-1560871710.45-245506636870829/command.py && sleep 0'
<localhost> EXEC /bin/sh -c 'chown ideascube /var/tmp/ansible-tmp-1560871710.45-245506636870829/ /var/tmp/ansible-tmp-1560871710.45-245506636870829/command.py && sleep 0'
<localhost> EXEC /bin/sh -c 'sudo -H -S -n -u ideascube /bin/sh -c '"'"'echo BECOME-SUCCESS-bpnwnmpzfzhtoyvaxyzzhqyapkbjlznr; KALITE_PYTHON=/home/ideascube/venvs/kalite/bin/python KALITE_HOME=/data/kalite /usr/bin/python /var/tmp/ansible-tmp-1560871710.45-245506636870829/command.py'"'"' && sleep 0'
<localhost> EXEC /bin/sh -c 'rm -f -r /var/tmp/ansible-tmp-1560871710.45-245506636870829/ > /dev/null 2>&1 && sleep 0'
failed: [localhost] (item=en) => {
    "changed": true, 
    "cmd": [
        "/home/ideascube/venvs/kalite/bin/kalite", 
        "manage", 
        "retrievecontentpack", 
        "local", 
        "en", 
        "/data/kalite_pack_en.zip"
    ], 
    "delta": "0:11:08.141198", 
    "end": "2019-06-18 18:39:41.694341", 
    "invocation": {
        "module_args": {
            "_raw_params": "/home/ideascube/venvs/kalite/bin/kalite manage retrievecontentpack local en /data/kalite_pack_en.zip", 
            "_uses_shell": false, 
            "argv": null, 
            "chdir": null, 
            "creates": null, 
            "executable": null, 
            "removes": null, 
            "stdin": null, 
            "warn": true
        }
    }, 
    "item": "en", 
    "msg": "non-zero return code", 
    "rc": 1, 
    "start": "2019-06-18 18:28:33.553143", 
    "stderr": "Traceback (most recent call last):\n  File \"/home/ideascube/venvs/kalite/local/lib/python2.7/site-packages/kalite/packages/bundled/django/core/management/base.py\", line 224, in run_from_argv\n    self.execute(*args, **options.__dict__)\n  File \"/home/ideascube/venvs/kalite/local/lib/python2.7/site-packages/kalite/packages/bundled/fle_utils/django_utils/command.py\", line 141, in execute\n    super(LocaleAwareCommand, self).execute(*args, **kwargs)\n  File \"/home/ideascube/venvs/kalite/local/lib/python2.7/site-packages/kalite/packages/bundled/django/core/management/base.py\", line 263, in execute\n    output = self.handle(*args, **options)\n  File \"/home/ideascube/venvs/kalite/local/lib/python2.7/site-packages/kalite/distributed/management/commands/retrievecontentpack.py\", line 97, in handle\n    self.local(*args, **options)\n  File \"/home/ideascube/venvs/kalite/local/lib/python2.7/site-packages/kalite/distributed/management/commands/retrievecontentpack.py\", line 177, in local\n    self.process_content_pack(zf, lang)\n  File \"/home/ideascube/venvs/kalite/local/lib/python2.7/site-packages/kalite/distributed/management/commands/retrievecontentpack.py\", line 187, in process_content_pack\n    extract_assessment_items(zf, \"en\")\n  File \"/home/ideascube/venvs/kalite/local/lib/python2.7/site-packages/kalite/distributed/management/commands/retrievecontentpack.py\", line 245, in extract_assessment_items\n    zf.extractall(content_settings.ASSESSMENT_ITEM_ROOT, items)\n  File \"/usr/lib/python2.7/zipfile.py\", line 1043, in extractall\n    self.extract(zipinfo, path, pwd)\n  File \"/usr/lib/python2.7/zipfile.py\", line 1031, in extract\n    return self._extract_member(member, path, pwd)\n  File \"/usr/lib/python2.7/zipfile.py\", line 1087, in _extract_member\n    shutil.copyfileobj(source, target)\nIOError: [Errno 28] No space left on device", 
    "stderr_lines": [
        "Traceback (most recent call last):", 
        "  File \"/home/ideascube/venvs/kalite/local/lib/python2.7/site-packages/kalite/packages/bundled/django/core/management/base.py\", line 224, in run_from_argv", 
        "    self.execute(*args, **options.__dict__)", 
        "  File \"/home/ideascube/venvs/kalite/local/lib/python2.7/site-packages/kalite/packages/bundled/fle_utils/django_utils/command.py\", line 141, in execute", 
        "    super(LocaleAwareCommand, self).execute(*args, **kwargs)", 
        "  File \"/home/ideascube/venvs/kalite/local/lib/python2.7/site-packages/kalite/packages/bundled/django/core/management/base.py\", line 263, in execute", 
        "    output = self.handle(*args, **options)", 
        "  File \"/home/ideascube/venvs/kalite/local/lib/python2.7/site-packages/kalite/distributed/management/commands/retrievecontentpack.py\", line 97, in handle", 
        "    self.local(*args, **options)", 
        "  File \"/home/ideascube/venvs/kalite/local/lib/python2.7/site-packages/kalite/distributed/management/commands/retrievecontentpack.py\", line 177, in local", 
        "    self.process_content_pack(zf, lang)", 
        "  File \"/home/ideascube/venvs/kalite/local/lib/python2.7/site-packages/kalite/distributed/management/commands/retrievecontentpack.py\", line 187, in process_content_pack", 
        "    extract_assessment_items(zf, \"en\")", 
        "  File \"/home/ideascube/venvs/kalite/local/lib/python2.7/site-packages/kalite/distributed/management/commands/retrievecontentpack.py\", line 245, in extract_assessment_items", 
        "    zf.extractall(content_settings.ASSESSMENT_ITEM_ROOT, items)", 
        "  File \"/usr/lib/python2.7/zipfile.py\", line 1043, in extractall", 
        "    self.extract(zipinfo, path, pwd)", 
        "  File \"/usr/lib/python2.7/zipfile.py\", line 1031, in extract", 
        "    return self._extract_member(member, path, pwd)", 
        "  File \"/usr/lib/python2.7/zipfile.py\", line 1087, in _extract_member", 
        "    shutil.copyfileobj(source, target)", 
        "IOError: [Errno 28] No space left on device"
    ], 
    "stdout": "[INFO] [2019-06-18 18:28:52,061] kalite.updates.management.utils: Installing a local content pack.\n[INFO] [2019-06-18 18:29:12,090] kalite.updates.management.utils: Moving content files to the right place.\n[WARNING] [2019-06-18 18:29:12,383] kalite.i18n.base: No en_icu.js file found in locale_path /data/kalite/locale\n[WARNING] [2019-06-18 18:29:12,389] kalite.i18n.base: No en_icu.js file found in locale_path /data/kalite/locale\n[INFO] [2019-06-18 18:29:12,394] kalite.i18n.base: Writing i18nized js file to /data/kalite/content/locale/js/i18n/en.js", 
    "stdout_lines": [
        "[INFO] [2019-06-18 18:28:52,061] kalite.updates.management.utils: Installing a local content pack.", 
        "[INFO] [2019-06-18 18:29:12,090] kalite.updates.management.utils: Moving content files to the right place.", 
        "[WARNING] [2019-06-18 18:29:12,383] kalite.i18n.base: No en_icu.js file found in locale_path /data/kalite/locale", 
        "[WARNING] [2019-06-18 18:29:12,389] kalite.i18n.base: No en_icu.js file found in locale_path /data/kalite/locale", 
        "[INFO] [2019-06-18 18:29:12,394] kalite.i18n.base: Writing i18nized js file to /data/kalite/content/locale/js/i18n/en.js"
    ]
}

RUNNING HANDLER [restart uwsgi] ************************************************

RUNNING HANDLER [restart kiwix] ************************************************
    to retry, use: --limit @/var/lib/ansible/local/main.retry

PLAY RECAP *********************************************************************
localhost                  : ok=26   changed=13   unreachable=0    failed=1   

[15:39:43] STDERR:  [WARNING]: Consider using the unarchive module rather than running tar.  If
[15:39:43] STDERR: you need to use command because unarchive is insufficient you can add
[15:39:43] STDERR: warn=False to this command task or set command_warnings=False in ansible.cfg to
[15:39:43] STDERR: get rid of this message.
sudo sync
sudo shutdown -P 0
[15:39:49] STDERR: Shutdown scheduled for Tue 2019-06-18 18:39:48 EAT, use 'shutdown -c' to cancel.
VM is off.
[15:40:15] Installation failed: ssh command failed with status 2. cmd: sudo sh -c 'cd /var/lib/ansible/local && /usr/local/bin/ansible-playbook -vvv --inventory hosts --tags move-content,seal --extra-vars="@/var/lib/ansible/local/extra_vars.json" main.yml'

--- Exception Trace ---
Traceback (most recent call last):
  File "run_installation.py", line 341, in run_installation
  File "backend/ansiblecube.py", line 214, in run_phase_two
  File "backend/ansiblecube.py", line 66, in run
  File "backend/qemu.py", line 419, in exec_cmd
backend.qemu.QemuException: ssh command failed with status 2. cmd: sudo sh -c 'cd /var/lib/ansible/local && /usr/local/bin/ansible-playbook -vvv --inventory hosts --tags move-content,seal --extra-vars="@/var/lib/ansible/local/extra_vars.json" main.yml'

---
Restoring system sleep policy
Resuming xdg-screensaver (wid #None)
*** DURATIONS SUMMARY ***
[1/5] Retrieve Master Image: 1 minute and 22.64 seconds (Tue Jun 18 13:33:45 2019 to Tue Jun 18 13:35:08 2019)
[2/5] Download contents: 52 minutes and 4.27 seconds (Tue Jun 18 13:35:08 2019 to Tue Jun 18 14:27:12 2019)
[3/5] Image configuration (virtualized): 31 minutes and 43.11 seconds (Tue Jun 18 14:27:12 2019 to Tue Jun 18 14:58:55 2019)
[4/5] Copy contents onto image: 11 minutes and 17.03 seconds (Tue Jun 18 14:58:55 2019 to Tue Jun 18 15:10:12 2019)
[5/5] Post-process contents (virtualized): 30 minutes and 3.2 seconds (Tue Jun 18 15:10:12 2019 to Tue Jun 18 15:40:15 2019)
TOTAL: 2 hours, 6 minutes and 30.27 seconds (Tue Jun 18 13:33:45 2019 to Tue Jun 18 15:40:15 2019)```

Popolechien commented 5 years ago

"No space left on device" - did I read this correctly? Also the user reported that he got two notifications - one for success and one for failure.

rgaudin commented 5 years ago

The “No space left on device” applies to the image running inside qemu, not the actual demo server (checked, there's plenty of space). It is possible the required space for this content was underestimated:

Content (all) were copied properly on /data partition.
Extraction of copied archive (here langpack_en_0.17.zip – 887MB) failed.

After this, kalite would also scan the videos and write some metadata into its database (few dozens of MB max I guess) but Aflatoun would also extract its language pack (800KB).

Realized looking at the log that I need to restart your worker as it's not running the latest version (without ideascube).

So this belongs to framagit.

As for the email, he receive the initial email (order created) and then the build failure.


"content": {
        "aflatoun": true,
        "edupi": true,
        "edupi_resources": null,
        "kalite": [
            "en"
        ],
        "wikifundi": [],
        "zims": [
            "wikibooks_en_all_novid.en",
            "wikipedia_en_all_novid.en",
            "wiktionary_en_all_novid.en",
            "tedmed_en_all.en",
            "ted_en_technology.en",
            "ted_en_science.en",
            "ted_en_global_issues.en",
            "ted_en_entertainment.en",
            "ted_en_design.en",
            "ted_en_business.en"
        ]
    }

Popolechien commented 5 years ago

Ok then just to be clear - can we restart the process once the worker is updated (and when)?

Popolechien commented 5 years ago

Failed again - albeit differently:


updating task #5d0b194b98c8bf0f67702ade status to: building
Starting image creation
Starting /usr/bin/kiwix-hotspot cli --root --filename 5d0b194b98c8bf0f67702ab9 --build-dir /data --config /data/5d0b194b98c8bf0f67702ab9.json --size 256GB

installer started: <subprocess.Popen object at 0x7f36f9c99e48>
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
periodic log upload..................
sending logs for task #5d0b194b98c8bf0f67702ade.
installer failed: 0
collecting full terminated log
installer rc: 0
Traceback (most recent call last):
  File "worker/tasks/create.py", line 103, in run
    getattr(self, method)()
  File "worker/tasks/create.py", line 188, in build_image
    raise subprocess.SubprocessError("installer rc: {}".format(ps.returncode))
subprocess.SubprocessError: installer rc: 0
updating task #5d0b194b98c8bf0f67702ade status to: failed_to_build
job is not alive
job crashed: installer rc: 0```

rgaudin commented 5 years ago

No it's the same, you're looking at a different log. There's no chance it would have succeeded as this is an installer bug and it hasn't been fixed/deployed yet. Will keep this open until it's deployed.

Popolechien commented 5 years ago

Ah yes, sorry ^^

rgaudin commented 5 years ago

So to be clear:

It's an estimation problem inside the installer.
It's an edge case where the margin doesn't cover the approximation in calculation.
I am working on it: adjusting calculation and testing but it takes time due to the size of the config (and we need that one to replicate the bug).
I'll communicate once this is: fixed in installer, released, deployed in the cardshop.

Keep in mind that fixing the estimation might mean that the content can't fit into 256GB and thus some content might need to be removed.

Popolechien commented 5 years ago

No problem. Am I right then to understand that creating a 256 Gb card (=super large) is what started the issue?

rgaudin commented 5 years ago

No, the cause is that almost all projects are included and that very few free space was left.

ZIM files are not transformed so what we account for == was goes into the image. For the projects, it's different as there are setup steps that builds and extract stuff.

kelson42 commented 5 years ago

This has been fixed in Kiwix Hotspot 2.0.7

offspot / imager-service

Card creation failed if content fills the SD card to almost 100% #93