YunoHost command not ending

beelm · May 3, 2020, 2:13pm

My YunoHost server

Hardware: VPS bought online
YunoHost version: 3.7.1.3
I have access to my server : Through SSH | through the webadmin
Are you in a special context or did you perform some particular tweaking on your YunoHost instance ? : no
If yes, please explain:

Description of my issue

Hello. While updating the Gitea app, the the YunoHost command seems to have gotten stuck. The backup appears to have completed, but new commands can not be taken. The last lines of the log before the issue came up:

2020-05-01 07:36:20,182 DEBUG    yunohost.backup _collect_app_files - [6161.1] Backup permission for app gitea
2020-05-01 07:36:20,199 DEBUG    moulinette.authenticator.ldap __init__ - initialize authenticator 'as-root' with: uri='ldapi://%2Fvar%2Frun%2Fslapd%2Fldapi', base_dn='d
c=yunohost,dc=org', user_rdn='gidNumber=0+uidNumber=0,cn=peercred,cn=external,cn=auth'
2020-05-01 07:36:20,266 INFO     yunohost.backup backup_create - [6161.1] Creating a backup archive from the collected files<E2><80><A6>
2020-05-01 07:36:20,266 DEBUG    yunohost.backup backup - [6161.1] Creating the backup TAR archive<E2><80><A6>
2020-05-01 07:38:16,709 DEBUG    yunohost.backup backup - [6161.1] TAR backup archive created
2020-05-01 07:38:16,709 SUCCESS  yunohost.backup success - [6161.1] Backup created
2020-05-01 07:38:16,710 DEBUG    moulinette.actionsmap process - action [6161.1] executed in 120.074s
2020-05-01 07:38:16,902 DEBUG    moulinette.actionsmap __init__ - loading actions map namespace 'yunohost'
2020-05-01 07:38:16,915 DEBUG    moulinette.actionsmap __init__ - extra parameter classes loaded: ['comment', 'ask', 'password', 'required', 'pattern']
2020-05-01 07:38:16,915 DEBUG    moulinette.interface __init__ - initializing base actions map parser for cli
2020-05-01 07:38:16,916 DEBUG    moulinette.interface __init__ - registering new callback action 'yunohost.utils.packages.ynh_packages_version' to ['-v', '--version']
2020-05-01 07:38:16,948 DEBUG    moulinette.core set_locale - unable to load locale 'en' from '/usr/share/moulinette/locale'
2020-05-01 07:38:16,948 DEBUG    moulinette.core set_locale - unable to load locale 'en' from '/usr/lib/moulinette/yunohost/locales'
2020-05-01 07:38:16,949 DEBUG    moulinette.core acquire - acquiring lock...
2020-05-01 07:38:17,016 DEBUG    moulinette.actionsmap process - loading python module yunohost.backup took 0.050s
2020-05-01 07:38:17,017 INFO     moulinette.actionsmap process - processing action [6409.1]: yunohost.backup.list with args={'human_readable': False, 'with_info': False}
2020-05-01 07:38:17,017 DEBUG    moulinette.actionsmap process - action [6409.1] executed in 0.000s
2020-05-02 01:00:07,319 DEBUG    moulinette.actionsmap __init__ - loading actions map namespace 'yunohost'
2020-05-02 01:00:08,063 DEBUG    moulinette.actionsmap __init__ - extra parameter classes loaded: ['comment', 'ask', 'password', 'required', 'pattern']
2020-05-02 01:00:08,063 DEBUG    moulinette.interface __init__ - initializing base actions map parser for cli
2020-05-02 01:00:08,064 DEBUG    moulinette.interface __init__ - registering new callback action 'yunohost.utils.packages.ynh_packages_version' to ['-v', '--version']
2020-05-02 01:00:08,102 DEBUG    moulinette.core set_locale - unable to load locale 'en' from '/usr/share/moulinette/locale'
2020-05-02 01:00:08,102 DEBUG    moulinette.core set_locale - unable to load locale 'en' from '/usr/lib/moulinette/yunohost/locales'
2020-05-02 01:00:08,103 DEBUG    moulinette.core acquire - acquiring lock...
2020-05-02 01:00:23,328 WARNING  moulinette.core acquire - Another YunoHost command is running right now, we are waiting for it to finish before running this one
2020-05-02 01:01:08,561 WARNING  moulinette.core acquire - Still waiting...
2020-05-02 01:04:08,431 WARNING  moulinette.core acquire - Still waiting...
2020-05-02 01:16:08,466 WARNING  moulinette.core acquire - Still waiting...
2020-05-02 02:04:08,525 WARNING  moulinette.core acquire - Still waiting...
2020-05-02 05:16:08,587 WARNING  moulinette.core acquire - Still waiting...

Since then, I can still use access the webadmin panel, but on clicks on for example System Update, it just keeps loading.

Trying a YunoHost command via SSH cannot acquire a log with the following error again:

WARNING  moulinette.core acquire - Another YunoHost command is running right now, we are waiting for it to finish before running this one

So it is not possible to do any backups or updates now.

Everything besides Gitea still works, so I assume the upgrade of Gitea did not complete. Does anyone have a suggestion what the safest way to to stop the process is, without danger of any data loss. Whatever is on Gitea is not so important for me, so it doesn’t have to be recovered, but I don’t want it to affect other data I have on the server (e.g. E-Mail, Nextcloud, …).

Thanks!

Aleks · May 3, 2020, 2:21pm

Hmokay that’s weird …

Naively I would try to : cat /var/run/moulinette_yunohost.lock

that should print a number (PID)

Then run : ps -ef | grep <thenumberyougot>

beelm · May 3, 2020, 2:42pm

root      6029 12552  0 May01 ?        00:00:00 sh -c YNH_APP_INSTANCE_NUMBER=1 YNH_CWD=/var/cache/yunohost/from_file/gitea_ynh-3365066a7671674b90c43de2cb975df83b9e84b5/scripts YNH_STDINFO=/tmp/tmpJTIOOn/stdinfo YNH_APP_INSTANCE_NAME=gitea YNH_INTERFACE=api YNH_APP_ID=gitea YNH_STDRETURN=/tmp/tmpcSBo7c/stdreturn BASH_XTRACEFD=7 /bin/bash -x "./upgrade" gitea 7>&1
root      6031 12552  0 May01 ?        00:00:00 /usr/bin/python /usr/bin/yunohost-api
root      6032 12552  0 May01 ?        00:00:00 /usr/bin/python /usr/bin/yunohost-api
root      6033 12552  0 May01 ?        00:06:36 /usr/bin/python /usr/bin/yunohost-api
root     11973 10963  0 16:39 pts/0    00:00:00 grep 12552
root     12552     1  0 Apr30 ?        00:04:46 /usr/bin/python /usr/bin/yunohost-api

Okay, thanks, it is definitely a problem with the Gitea upgrade process. Is it possible to just run kill 6029?

Aleks · May 3, 2020, 2:47pm

Hmmmm nope … there might still be other things to do

If you run ps -ef | grep yunohost do you see any other line that seems interesting ? Im suspecting a yunohost --version … I would try to kill that one

(Edit: N.B: it helps if you can share the output of ps -ef | grep yunohost to try to understand how the bug happens so that we can fix upstream)

beelm · May 3, 2020, 3:00pm

ps -ef | grep yunohost
avahi      681     1  0  2019 ?        00:00:04 avahi-daemon: running [yunohost.local]
root      2349  2088  0 May02 ?        00:00:00 /bin/bash /etc/cron.daily/yunohost-certificate-renew
root      2350  2349  0 May02 ?        00:08:15 /usr/bin/python /usr/bin/yunohost domain cert-renew --email
root      6029 12552  0 May01 ?        00:00:00 sh -c YNH_APP_INSTANCE_NUMBER=1 YNH_CWD=/var/cache/yunohost/from_file/gitea_ynh-3365066a7671674b90c43de2cb975df83b9e84b5/scripts YNH_STDINFO=/tmp/tmpJTIOOn/stdinfo YNH_APP_INSTANCE_NAME=gitea YNH_INTERFACE=api YNH_APP_ID=gitea YNH_STDRETURN=/tmp/tmpcSBo7c/stdreturn BASH_XTRACEFD=7 /bin/bash -x "./upgrade" gitea 7>&1
root      6031 12552  0 May01 ?        00:00:00 /usr/bin/python /usr/bin/yunohost-api
root      6032 12552  0 May01 ?        00:00:00 /usr/bin/python /usr/bin/yunohost-api
root      6033 12552  0 May01 ?        00:06:38 /usr/bin/python /usr/bin/yunohost-api
root     12335 12324  0 16:55 pts/0    00:00:00 grep yunohost
root     12552     1  0 Apr30 ?        00:04:48 /usr/bin/python /usr/bin/yunohost-api
root     24273 24271  0 01:00 ?        00:00:00 sudo BACKUP_CORE_ONLY=1 yunohost backup create
root     24277 24273  0 01:00 ?        00:03:42 /usr/bin/python /usr/bin/yunohost backup create
root     28669 28665  0 May02 ?        00:00:00 sudo BACKUP_CORE_ONLY=1 yunohost backup create
root     28673 28669  0 May02 ?        00:09:32 /usr/bin/python /usr/bin/yunohost backup create
root     29896 29689  0 06:25 ?        00:00:00 /bin/bash /etc/cron.daily/yunohost-certificate-renew
root     29897 29896  0 06:25 ?        00:02:30 /usr/bin/python /usr/bin/yunohost domain cert-renew --email
matrix-+ 32378     1  0 Apr20 ?        00:43:33 /opt/yunohost/matrix-synapse/bin/python -m synapse.app.homeserver --config-path=/etc/matrix-synapse/homeserver.yaml --config-path=/etc/matrix-synapse/conf.d/

That’s the whole output. No yunohost --version running.

Aleks · May 3, 2020, 3:06pm

Hmyes my bad I misread the log … in fact the log you pasted on first post does not tell what command is being attempted to run … I’m guessing you got this from yunohost-cli or api.log in /var/log/yunohost ?

Can you try instead of go to /var/log/yunohost/categories/operation/ and run 'ls -thor' to try to find the log of the upgrade still running ? Then 'tail -n 100 <thelogyoufound>.log'

beelm · May 3, 2020, 3:13pm

tail -n 100 20200501-053614-app_upgrade-gitea.log 
2020-05-01 07:38:19,635: DEBUG - + ynh_handle_getopts_args --file=/etc/nginx/conf.d/MYDOMAIN.TLD.d/gitea.conf
2020-05-01 07:38:19,635: DEBUG - + set +x
2020-05-01 07:38:19,635: DEBUG - + local checksum_setting_name=checksum__etc_nginx_conf.d_MYDOMAIN.TLD.d_gitea.conf
2020-05-01 07:38:19,636: DEBUG - ++ md5sum /etc/nginx/conf.d/MYDOMAIN.TLD.d/gitea.conf
2020-05-01 07:38:19,636: DEBUG - ++ cut '-d ' -f1
2020-05-01 07:38:19,636: DEBUG - + ynh_app_setting_set --app=gitea --key=checksum__etc_nginx_conf.d_MYDOMAIN.TLD.d_gitea.conf --value=5780cc51d6290e53e4c01ebf7d4e5215
2020-05-01 07:38:19,636: DEBUG - + local legacy_args=akv
2020-05-01 07:38:19,636: DEBUG - + args_array=([a]=app= [k]=key= [v]=value=)
2020-05-01 07:38:19,636: DEBUG - + declare -Ar args_array
2020-05-01 07:38:19,637: DEBUG - + local app
2020-05-01 07:38:19,637: DEBUG - + local key
2020-05-01 07:38:19,637: DEBUG - + local value
2020-05-01 07:38:19,637: DEBUG - + ynh_handle_getopts_args --app=gitea --key=checksum__etc_nginx_conf.d_MYDOMAIN.TLD.d_gitea.conf --value=5780cc51d6290e53e4c01ebf7d4e5215
2020-05-01 07:38:19,637: DEBUG - + set +x
2020-05-01 07:38:19,637: DEBUG - + ynh_app_setting set gitea checksum__etc_nginx_conf.d_MYDOMAIN.TLD.d_gitea.conf 5780cc51d6290e53e4c01ebf7d4e5215
2020-05-01 07:38:19,638: DEBUG - + [[ set == \d\e\l\e\t\e ]]
2020-05-01 07:38:19,638: DEBUG - + ACTION=set
2020-05-01 07:38:19,638: DEBUG - + APP=gitea
2020-05-01 07:38:19,638: DEBUG - + KEY=checksum__etc_nginx_conf.d_MYDOMAIN.TLD.d_gitea.conf
2020-05-01 07:38:19,638: DEBUG - + VALUE=5780cc51d6290e53e4c01ebf7d4e5215
2020-05-01 07:38:19,638: DEBUG - + python2.7 -
2020-05-01 07:38:19,739: DEBUG - + [[ checksum__etc_nginx_conf.d_MYDOMAIN.TLD.d_gitea.conf =~ ^(unprotected|skipped)_ ]]
2020-05-01 07:38:19,739: WARNING - Reload the service nginx
2020-05-01 07:38:19,740: DEBUG - + '[' -n '' ']'
2020-05-01 07:38:19,740: DEBUG - + unset backup_file_checksum
2020-05-01 07:38:19,740: DEBUG - + ynh_systemd_action --service_name=nginx --action=reload
2020-05-01 07:38:19,740: DEBUG - + args_array=([n]=service_name= [a]=action= [l]=line_match= [p]=log_path= [t]=timeout= [e]=length=)
2020-05-01 07:38:19,740: DEBUG - + declare -Ar args_array
2020-05-01 07:38:19,741: DEBUG - + local service_name
2020-05-01 07:38:19,741: DEBUG - + local action
2020-05-01 07:38:19,741: DEBUG - + local line_match
2020-05-01 07:38:19,741: DEBUG - + local length
2020-05-01 07:38:19,741: DEBUG - + local log_path
2020-05-01 07:38:19,742: DEBUG - + local timeout
2020-05-01 07:38:19,742: DEBUG - + ynh_handle_getopts_args --service_name=nginx --action=reload
2020-05-01 07:38:19,742: DEBUG - + set +x
2020-05-01 07:38:19,742: DEBUG - + local service_name=nginx
2020-05-01 07:38:19,742: DEBUG - + local action=reload
2020-05-01 07:38:19,742: DEBUG - + local log_path=/var/log/nginx/nginx.log
2020-05-01 07:38:19,743: DEBUG - + local length=20
2020-05-01 07:38:19,743: DEBUG - + local timeout=300
2020-05-01 07:38:19,743: DEBUG - + [[ -n '' ]]
2020-05-01 07:38:19,743: DEBUG - + echo 'Reload the service nginx'
2020-05-01 07:38:19,743: DEBUG - + systemctl reload nginx
2020-05-01 07:38:19,944: DEBUG - + [[ -n '' ]]
2020-05-01 07:38:19,944: DEBUG - + ynh_script_progression '--message=Upgrading database and sources...' --weight=6
2020-05-01 07:38:19,945: DEBUG - + set +x
2020-05-01 07:38:19,945: DEBUG - + set +x
2020-05-01 07:38:19,945: DEBUG - + echo '! Helper used in legacy mode !'
2020-05-01 07:38:19,945: DEBUG - + set +x
2020-05-01 07:38:19,945: DEBUG - + echo '[##########++++......] > Upgrading database and sources...'
2020-05-01 07:38:19,946: DEBUG - + set -x
2020-05-01 07:38:19,946: DEBUG - + '[' -z 1.10.3 ']'
2020-05-01 07:38:19,946: DEBUG - + case $upstream_version in
2020-05-01 07:38:19,946: DEBUG - + ynh_setup_source /opt/gitea source/x86-64
2020-05-01 07:38:19,946: DEBUG - + local legacy_args=ds
2020-05-01 07:38:19,946: DEBUG - + args_array=([d]=dest_dir= [s]=source_id=)
2020-05-01 07:38:19,947: DEBUG - + declare -Ar args_array
2020-05-01 07:38:19,947: DEBUG - + local dest_dir
2020-05-01 07:38:19,947: DEBUG - + local source_id
2020-05-01 07:38:19,947: DEBUG - + ynh_handle_getopts_args /opt/gitea source/x86-64
2020-05-01 07:38:19,947: DEBUG - + set +x
2020-05-01 07:38:19,947: DEBUG - + echo '! Helper used in legacy mode !'
2020-05-01 07:38:19,948: DEBUG - + set +x
2020-05-01 07:38:19,948: DEBUG - + source_id=source/x86-64
2020-05-01 07:38:19,948: DEBUG - + local src_file_path=/var/cache/yunohost/from_file/gitea_ynh-3365066a7671674b90c43de2cb975df83b9e84b5/scripts/../conf/source/x86-64.src
2020-05-01 07:38:19,948: DEBUG - + '[' '!' -e /var/cache/yunohost/from_file/gitea_ynh-3365066a7671674b90c43de2cb975df83b9e84b5/scripts/../conf/source/x86-64.src ']'
2020-05-01 07:38:19,948: DEBUG - ++ cut -d= -f2-
2020-05-01 07:38:19,949: DEBUG - ++ grep SOURCE_URL= /var/cache/yunohost/from_file/gitea_ynh-3365066a7671674b90c43de2cb975df83b9e84b5/scripts/../conf/source/x86-64.src
2020-05-01 07:38:19,949: DEBUG - + local src_url=https://github.com/go-gitea/gitea/releases/download/v1.11.4/gitea-1.11.4-linux-amd64
2020-05-01 07:38:19,949: DEBUG - ++ cut -d= -f2-
2020-05-01 07:38:19,949: DEBUG - ++ grep SOURCE_SUM= /var/cache/yunohost/from_file/gitea_ynh-3365066a7671674b90c43de2cb975df83b9e84b5/scripts/../conf/source/x86-64.src
2020-05-01 07:38:19,949: DEBUG - + local src_sum=4408c781069c36cbb1b5923ae924e67ceee661ba9c9bd6c73cd7408c9cd62af6
2020-05-01 07:38:19,949: DEBUG - ++ grep SOURCE_SUM_PRG= /var/cache/yunohost/from_file/gitea_ynh-3365066a7671674b90c43de2cb975df83b9e84b5/scripts/../conf/source/x86-64.src
2020-05-01 07:38:19,950: DEBUG - ++ cut -d= -f2-
2020-05-01 07:38:19,950: DEBUG - + local src_sumprg=sha256sum
2020-05-01 07:38:19,950: DEBUG - ++ grep SOURCE_FORMAT= /var/cache/yunohost/from_file/gitea_ynh-3365066a7671674b90c43de2cb975df83b9e84b5/scripts/../conf/source/x86-64.src
2020-05-01 07:38:19,950: DEBUG - ++ cut -d= -f2-
2020-05-01 07:38:19,950: DEBUG - + local src_format=
2020-05-01 07:38:19,950: DEBUG - ++ cut -d= -f2-
2020-05-01 07:38:19,951: DEBUG - ++ grep SOURCE_EXTRACT= /var/cache/yunohost/from_file/gitea_ynh-3365066a7671674b90c43de2cb975df83b9e84b5/scripts/../conf/source/x86-64.src
2020-05-01 07:38:19,951: DEBUG - + local src_extract=false
2020-05-01 07:38:19,951: DEBUG - ++ cut -d= -f2-
2020-05-01 07:38:19,951: DEBUG - ++ grep SOURCE_IN_SUBDIR= /var/cache/yunohost/from_file/gitea_ynh-3365066a7671674b90c43de2cb975df83b9e84b5/scripts/../conf/source/x86-64.src
2020-05-01 07:38:19,951: DEBUG - + local src_in_subdir=
2020-05-01 07:38:19,951: DEBUG - ++ cut -d= -f2-
2020-05-01 07:38:19,952: DEBUG - ++ grep SOURCE_FILENAME= /var/cache/yunohost/from_file/gitea_ynh-3365066a7671674b90c43de2cb975df83b9e84b5/scripts/../conf/source/x86-64.src
2020-05-01 07:38:19,952: DEBUG - + local src_filename=gitea
2020-05-01 07:38:19,952: DEBUG - + src_sumprg=sha256sum
2020-05-01 07:38:19,952: DEBUG - + src_in_subdir=true
2020-05-01 07:38:19,952: DEBUG - + src_format=tar.gz
2020-05-01 07:38:19,953: DEBUG - ++ tr '[:upper:]' '[:lower:]'
2020-05-01 07:38:19,953: DEBUG - ++ echo tar.gz
2020-05-01 07:38:19,953: DEBUG - + src_format=tar.gz
2020-05-01 07:38:19,953: DEBUG - + src_extract=false
2020-05-01 07:38:19,953: DEBUG - + '[' gitea = '' ']'
2020-05-01 07:38:19,953: INFO - [##########++++......] > Upgrading database and sources...
2020-05-01 07:38:19,956: DEBUG - + local local_src=/opt/yunohost-apps-src/gitea/gitea
2020-05-01 07:38:19,957: DEBUG - + test -e /opt/yunohost-apps-src/gitea/gitea
2020-05-01 07:38:19,957: DEBUG - ++ wget -nv -O gitea https://github.com/go-gitea/gitea/releases/download/v1.11.4/gitea-1.11.4-linux-amd64

The Gitea Upgrade was the last available log in that folder. Stopped during wget maybe.

Aleks · May 3, 2020, 3:14pm

Hmokay … let’s try to confirm that wget is still running by trying : ps -ef | grep -B2 wget

beelm · May 3, 2020, 3:16pm

ps -ef | grep -B2 wget
root      6415     1  0 Apr18 ?        00:00:01 nginx: master process /usr/sbin/nginx -g daemon on; master_process on;
root      6786  6030  0 May01 ?        00:00:00 /bin/bash -x ./upgrade gitea
root      6787  6786  0 May01 ?        00:00:00 wget -nv -O gitea https://github.com/go-gitea/gitea/releases/download/v1.11.4/gitea-1.11.4-linux-amd64

Yes, it’s still running. Killable?

Aleks · May 3, 2020, 3:16pm

I would say yes Conclusion is: we should add a timeout when we run wgets … I’ll open a fix for that, thanks !

beelm · May 3, 2020, 3:19pm

Okay, thanks for your help. Upgrade ended in an error, but otherwise seems to run again!

Aleks · May 3, 2020, 3:47pm

Followup: https://github.com/YunoHost/yunohost/pull/972

system · May 18, 2020, 3:47pm

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