Mise à jour de l'application qui se bloque indéfiniment

jmdesprez · October 29, 2019, 6:18pm

Mon serveur YunoHost

Matériel: VPS acheté en ligne (fournisseur OVH)
Version de YunoHost:

$ yunohost --version
yunohost: 
  repo: stable
  version: 3.6.5.3
yunohost-admin: 
  repo: stable
  version: 3.6.5
moulinette: 
  repo: stable
  version: 3.6.4.1
ssowat: 
  repo: stable
  version: 3.6.4

J’ai accès à mon serveur : En SSH | Par la webadmin
Je fais principalement les actions en ligne de commande, je suis root sur la machine.

Êtes-vous dans un contexte particulier ou avez-vous effectué des modificiations particulières sur votre instance ? : non

Description du problème

Bonjour à tous

Il y a certaines applications que je n’arrive pas à mettre à jour.

Le symptôme est toujours le même, la mise à jour se bloque et l’invite de commande ne rend pas la main. Sachant que j’attends assez longtemps (j’ai laissé jusqu’a 15 minutes) et que je fini par arrêter le process avec un ctrl+c

Comme je n’ai pas de message d’erreur, c’est assez compliqué de chercher sur le forum

J’ai quand même cherché des infos et j’ai vu que certains problèmes peuvent être causés par la version de python. Mais cela semble ok pour moi :

$ python --version
Python 2.7.13

J’ai aussi lancé une regénération des configurations. Cela m’a indiqué que des configurations avaient été changées. Le truc c’est que je n’ai pas changé les configurations en question. Donc j’ai noté les différences et j’ai regénéré en forçant.

J’ai aussi lancé la commande en mode debug (je vous mets juste les dernières lignes) :

$ yunohost --debug tools upgrade --apps gitea
[...]
39684 DEBUG +++ ynh_read_manifest --manifest=../manifest.json --manifest_key=version
39684 DEBUG +++ args_array=([m]=manifest= [k]=manifest_key=)
39684 DEBUG +++ declare -Ar args_array
39684 DEBUG +++ local manifest
39685 DEBUG +++ local manifest_key
39685 DEBUG +++ ynh_handle_getopts_args --manifest=../manifest.json --manifest_key=version
39686 DEBUG +++ set +x

Et ensuite plus rien, le process tourne toujours et ne rend pas la main.

J’ai trouvé un truc intéressant avec un htop.

Un process est à 27% de cpu : /bin/bash -x ./upgrade gitea
Ce process spawn parfois d’autres process qui se terminent, sauf qu’il les relances en boucle. Parmis les process relancés, j’ai vu brievement un seq 0 0 et aussi /bin/bash -x ./upgrade gitea (donc exactement la même commande)

Quand je quitte l’application, j’ai une stack trace qui m’indique que c’est “moulinette” qui semble être bloqué, en attente d’un fichier

^CProcess AsynchronousFileReader-3:
Process AsynchronousFileReader-2:
Traceback (most recent call last):
  File "/usr/lib/python2.7/multiprocessing/process.py", line 258, in _bootstrap
    self.run()
Process AsynchronousFileReader-1:
Traceback (most recent call last):
  File "/usr/lib/python2.7/multiprocessing/process.py", line 258, in _bootstrap
    self.run()
118030 DEBUG action [23365.1] executed in 117.777s
Traceback (most recent call last):
  File "/usr/lib/python2.7/multiprocessing/process.py", line 258, in _bootstrap
    self.run()
  File "/usr/lib/python2.7/dist-packages/moulinette/utils/stream.py", line 60, in run
    time.sleep(0.05)
KeyboardInterrupt
  File "/usr/lib/python2.7/dist-packages/moulinette/utils/stream.py", line 37, in run
    for line in iter(self._fd.readline, ''):
KeyboardInterrupt
118034 DEBUG lock has been released
  File "/usr/lib/python2.7/dist-packages/moulinette/utils/stream.py", line 37, in run
    for line in iter(self._fd.readline, ''):
KeyboardInterrupt

Je suis allez voir dans /usr/lib/python2.7/dist-packages/moulinette/utils/stream.py et j’ai l’impression que la boucle ne s’arrête jamais (on passe toujours par la ligne 60 pour attendre et on relance)

$ awk 'NR==30,NR==65' /usr/lib/python2.7/dist-packages/moulinette/utils/stream.py
    def run(self):
        """The body of the tread: read lines and put them on the queue."""

        # If self._fd is a file opened with open()...
        # Typically that's for stdout/stderr pipes
        # We can read the stuff easily with 'readline'
        if not isinstance(self._fd, int):
            for line in iter(self._fd.readline, ''):
                self._queue.put(line)

        # Else, it got opened with os.open() and we have to read it
        # wit low level crap...
        else:
            data = ""
            while True:
                # Try to read (non-blockingly) a few bytes, append them to
                # the buffer
                data += os.read(self._fd, 50)

                # If nobody's writing in there anymore, get out
                if not data and os.fstat(self._fd).st_nlink == 0:
                    return

                # If we have data, extract a line (ending with \n) and feed
                # it to the consumer
                if data and '\n' in data:
                    lines = data.split('\n')
                    self._queue.put(lines[0])
                    data = '\n'.join(lines[1:])
                else:
                    time.sleep(0.05)

    def eof(self):
        """Check whether there is no more content to expect."""
        return not self.is_alive() and self._queue.empty()

Là je suis un peu bloqué car je ne sais pas quel flux est lu.

Du coup j’ai tenté un lsof avec le pid du process qui boucle sur le time.sleep(0.05) :

$ lsof -p 29582
COMMAND   PID USER   FD   TYPE DEVICE SIZE/OFF    NODE NAME
bash    29582 root  cwd    DIR  254,1     4096   33163 /var/cache/yunohost/from_file/gitea_ynh-113d5973f4700cc5718903f5e522b1624d4d76f4/scripts
bash    29582 root  rtd    DIR  254,1     4096       2 /
bash    29582 root  txt    REG  254,1  1168776   41286 /bin/bash
bash    29582 root  mem    REG  254,1  1689360   60509 /lib/x86_64-linux-gnu/libc-2.24.so
bash    29582 root  mem    REG  254,1    14640   60524 /lib/x86_64-linux-gnu/libdl-2.24.so
bash    29582 root  mem    REG  254,1   153288   57537 /lib/x86_64-linux-gnu/ld-2.24.so
bash    29582 root  mem    REG  254,1  1683408   50122 /usr/lib/locale/locale-archive
bash    29582 root  mem    REG  254,1   183528   60391 /lib/x86_64-linux-gnu/libtinfo.so.6.1
bash    29582 root  mem    REG  254,1    26258  312102 /usr/lib/x86_64-linux-gnu/gconv/gconv-modules.cache
bash    29582 root    0u   CHR  136,0      0t0       3 /dev/pts/0
bash    29582 root    1w  FIFO    0,8      0t0 3716647 pipe
bash    29582 root    2w  FIFO    0,8      0t0 3685128 pipe
bash    29582 root    3w   REG  254,1  6174269  157385 /var/log/yunohost/yunohost-cli.log
bash    29582 root    4r  FIFO    0,8      0t0 3856926 pipe
bash    29582 root    5w   REG  254,1    96413  164373 /var/log/yunohost/categories/operation/20191029-174643-app_upgrade-gitea.log
bash    29582 root    6r  FIFO  254,1      0t0  254173 /tmp/tmpC5c3o4/stdinfo
bash    29582 root    7w  FIFO    0,8      0t0 3685127 pipe

Sachant que j’ai un pattern de boucle intéressant dans yunohost-cli.log:

2019-10-29 18:50:01,982 DEBUG    moulinette.interface __init__ - initializing base actions map parser for cli
2019-10-29 18:50:01,983 DEBUG    moulinette.interface __init__ - registering new callback action 'yunohost.utils.packages.ynh_packages_version' to ['-v', '--version']
2019-10-29 18:50:02,217 DEBUG    moulinette.core set_locale - unable to load locale 'en' from '/usr/share/moulinette/locale'
2019-10-29 18:50:02,217 DEBUG    moulinette.core set_locale - unable to load locale 'en' from '/usr/lib/moulinette/yunohost/locales'
2019-10-29 18:52:02,370 DEBUG    moulinette.actionsmap __init__ - loading actions map namespace 'yunohost'
2019-10-29 18:52:02,405 DEBUG    moulinette.actionsmap __init__ - extra parameter classes loaded: ['comment', 'ask', 'password', 'required', 'pattern']
2019-10-29 18:52:02,405 DEBUG    moulinette.interface __init__ - initializing base actions map parser for cli
2019-10-29 18:52:02,405 DEBUG    moulinette.interface __init__ - registering new callback action 'yunohost.utils.packages.ynh_packages_version' to ['-v', '--version']
2019-10-29 18:52:02,485 DEBUG    moulinette.core set_locale - unable to load locale 'en' from '/usr/share/moulinette/locale'
2019-10-29 18:52:02,485 DEBUG    moulinette.core set_locale - unable to load locale 'en' from '/usr/lib/moulinette/yunohost/locales'
2019-10-29 18:54:02,380 DEBUG    moulinette.actionsmap __init__ - loading actions map namespace 'yunohost'
2019-10-29 18:54:02,413 DEBUG    moulinette.actionsmap __init__ - extra parameter classes loaded: ['comment', 'ask', 'password', 'required', 'pattern']
2019-10-29 18:54:02,413 DEBUG    moulinette.interface __init__ - initializing base actions map parser for cli
2019-10-29 18:54:02,413 DEBUG    moulinette.interface __init__ - registering new callback action 'yunohost.utils.packages.ynh_packages_version' to ['-v', '--version']
2019-10-29 18:54:02,481 DEBUG    moulinette.core set_locale - unable to load locale 'en' from '/usr/share/moulinette/locale'
2019-10-29 18:54:02,485 DEBUG    moulinette.core set_locale - unable to load locale 'en' from '/usr/lib/moulinette/yunohost/locales'

J’ai regardé et la locale semble être là :

$ ls -l /usr/share/moulinette/locale
total 96
-rw-r--r-- 1 root root 4382 Aug  5 18:41 ar.json
-rw-r--r-- 1 root root    3 Aug  5 18:41 bn_BD.json
-rw-r--r-- 1 root root    3 Aug  5 18:41 br.json
-rw-r--r-- 1 root root 3465 Aug  5 18:41 ca.json
-rw-r--r-- 1 root root 2948 Aug  5 18:41 cmn.json
-rw-r--r-- 1 root root 2273 Aug  5 18:41 de.json
-rw-r--r-- 1 root root    3 Aug  5 18:41 el.json
-rw-r--r-- 1 root root 3254 Aug  5 18:41 en.json
-rw-r--r-- 1 root root   31 Aug  5 18:41 eo.json
-rw-r--r-- 1 root root 3474 Aug  5 18:41 es.json
-rw-r--r-- 1 root root   70 Aug  5 18:41 eu.json
-rw-r--r-- 1 root root 3729 Aug  5 18:41 fr.json
-rw-r--r-- 1 root root 3677 Aug  5 18:41 hi.json
-rw-r--r-- 1 root root    3 Aug  5 18:41 hu.json
-rw-r--r-- 1 root root 3479 Aug  5 18:41 it.json
-rw-r--r-- 1 root root    3 Aug  5 18:41 nb_NO.json
-rw-r--r-- 1 root root 3366 Aug  5 18:41 nl.json
-rw-r--r-- 1 root root 3659 Aug  5 18:41 oc.json
-rw-r--r-- 1 root root    3 Aug  5 18:41 pl.json
-rw-r--r-- 1 root root 3442 Aug  5 18:41 pt.json
-rw-r--r-- 1 root root 3842 Aug  5 18:41 ru.json
-rw-r--r-- 1 root root    3 Aug  5 18:41 sv.json
-rw-r--r-- 1 root root 1589 Aug  5 18:41 tr.json

Et le fichier semble être valide :

$jq '.' '/usr/share/moulinette/locale/en.json'
{
  "argument_required": "Argument '{argument}' is required",
  "authentication_profile_required": "Authentication to profile '{profile}' required",
  "authentication_required": "Authentication required",
[...]

Voila ou je me suis arrêté. Je ne sais pas si le problème vient du fichier locale et si oui pourquoi il n’est pas correctement chargé.

Pour info, j’ai testé avec piwigo et nextcloud et j’ai le même comportement.

Ha aussi, j’ai fait tout ça en ayant préalablement mis à jour et après un reboot

yunohost tools upgrade --system
Info: Nothing to do! Everything is already up to date!
Info: Upgrading packages…
Success! The system has been upgraded

J’ai aussi fait apt-get update apt-get dist-upgrade apt-get autoremove et apt-get autoclean

Merci pour votre aide

Aleks · October 29, 2019, 6:31pm

Oula, tu es parti un peu loin dans ton analyse … Mais félicitations d’une certaine manière d’avoir réussi à te dépatouiller avec tout ce code que tu ne connais pas

Tout ça c’'est “juste” la partie qui attends en parallèle que le script d’upgrade lui donne à manger des messages à afficher dans le log … c’est pas le “vrai” script d’upgrade

Le coeur du truc, c’est le script d’upgrade de l’application qui est censé tourner quelque part (c.f. l’appel ici) que tu devrais aussi pouvoir voir en faisant un ps -ef --forest …

Hmouai je ne sais pas trop ce qu’il en est vraiment, mais je ne m’en ferais pas trop pour ça, on a certains de ces mesages qui ne sont pas des vraies erreurs (même si là tout de suite ça me parrait tout de même étrange). Mais dans tout les cas, probablement pas de rapport avec ce soucis d’upgrade …

Je retournerais plutôt vers le point de départ avec ton log de yunohost --debug tools upgrade --apps gitea

Le truc c’est que la dernière ligne est set +x qui desactive le logging dans bash, car ce qu’il se passe dans ynh_handle_getopts_args est generalement peu intéressant … mais là en l’occurence il y a un truc qui bloque. Pas sur de piger quoi … mais il me semble avoir deja eu des solutions similaires.

Suivant à quel point tu es à l’aise, tu peux tenter de commenter la ligne correspondante (le set +x) dans /usr/share/yunohost/helpers.d/getopts et relancer le bouzin …

jmdesprez · October 30, 2019, 10:16am

Merci pour l’aide !

Oui je suis parti trop loin … Mais j’aime beaucoup ce que vous avez réussit à faire avec yunohost. Et c’était l’occasion d’essayer de comprendre ce qu’il se passe (je pense que c’est important).

Donc, j’en reviens à mon problème. J’ai fait les modifications et voila ce que j’ai dans le log :

148672 DEBUG +++ OPTIND=1
148673 DEBUG +++ local parameter=
148674 DEBUG +++ getopts :m:k: parameter
148675 DEBUG +++ '[' m = '?' ']'
148675 DEBUG +++ '[' m = : ']'
148676 DEBUG +++ local shift_value=1
148678 DEBUG +++ local option_var=manifest
148678 DEBUG +++ '[' = '!=' = ']'
148678 DEBUG +++ all_args=("$@")
148679 DEBUG +++ local all_args
148679 DEBUG +++ '[' 14 -gt 2 ']'
148680 DEBUG +++ all_args[0]=-m_key=version
148681 DEBUG +++ shift_value=0
148682 DEBUG +++ eval manifest=
148683 DEBUG ++++ manifest=
148685 DEBUG +++ local i
148685 DEBUG ++++ seq 0 0
148685 DEBUG +++ for i in `seq 0 $(( ${#all_args[@]} - 1 ))`
148686 DEBUG +++ '[' - == - ']'
148687 DEBUG +++ '[' 0 -ne 0 ']'
148687 DEBUG +++ shift 0
148687 DEBUG +++ '[' 1 -ne 0 ']'
148688 DEBUG +++ OPTIND=1

Donc mon problème c’est le shift 0 qui fait le que while va se relancer à l’infini.

Ca doit être décrémenté ici :

# If the first argument is longer than 2 characters,
# There's a value attached to the option, in the same array cell
if [ ${#all_args[0]} -gt 2 ]; then
  # Remove the option and the space, so keep only the value itself.
  all_args[0]="${all_args[0]#-${parameter} }"
  # Reduce the value of shift, because the option has been removed manually
  shift_value=$(( shift_value - 1 ))
fi

Je sais lire/faire du shell donc je comprend globalement mais je n’ai pas encore une vision claire.

Au cas ou, je mets ma version de bash :

$ bash --version
GNU bash, version 5.0.3(1)-release (x86_64-pc-linux-gnu)

jmdesprez · November 5, 2019, 2:19pm

Bon j’ai progressé (un peu)

En fait le problème vient exactement de cette ligne : all_args[0]="${all_args[0]#-${parameter} }"

Le truc c’est que all_args contient -m_key=version sauf que le parameter lui vaut m

Donc la substitution bash ne peut pas fonctionner :

déjà parce que c’est un = et pas un espace
de plus, il faut retirer -m_key=, pas juste -m

Pour info, getopts_parameters lui vaut m:k:

jmdesprez · November 19, 2019, 10:57am

Je n’ai malheureusement pas trouvé la solution.
Je vais laisser les applications en l’état sans faire les mises à jours le temps d’explorer d’autres pistes

system · December 4, 2019, 10:57am

This topic was automatically closed 15 days after the last reply. New replies are no longer allowed.