Failed to install on VPS

Describe the bug

A clear and concise description of what the bug is. Trying to install the app, have tried both webadmin and CLI without success. Both on root domain and subdomain.

Context

Hardware: VPS bought online. vmlinuz-4.19.0-16-amd64.
YunoHost version: YunoHost 4.3.4.2 (stable).
I have access to my server: SSH and webadmin
Using, or trying to install package version/branch: 4.2.1~ynh1

Steps to reproduce

If you performed a command from the CLI, the command itself is enough. For example: Through webadmin and CLI

sudo yunohost app install https://github.com/YunoHost-Apps/rocketchat_ynh --debug

Expected behavior

Installed app.

Logs

args: app: rocketchat args: domain=chat.maindomain.tld&path=%2F&admin=johns&is_public=0&password='**' force: false label: Chat no_remove_on_failure: false ended_at: 2021-12-13 17:09:27.882229 env: YNH_APP_ARG_ADMIN: johns YNH_APP_ARG_DOMAIN: chat.maindomain.tld YNH_APP_ARG_IS_PUBLIC: '0' YNH_APP_ARG_PATH: / YNH_APP_BASEDIR: /var/cache/yunohost/app_tmp_work_dirs/app_55je6c1e YNH_APP_ID: rocketchat YNH_APP_INSTANCE_NAME: rocketchat YNH_APP_INSTANCE_NUMBER: '1' YNH_APP_MANIFEST_VERSION: 4.2.1~ynh1 YNH_ARCH: amd64 error: An error occurred inside the app installation script interface: api operation: app_install parent: null related_to:

- app
- rocketchat started_at: 2021-12-13 17:03:33.614491 success: false yunohost_version: 4.3.4.2

============

2021-12-13 11:03:33,625: INFO - Installing rocketchat... 2021-12-13 11:03:33,791: DEBUG - Nothing to update in LDAP 2021-12-13 11:03:33,792: DEBUG - Permission 'rocketchat.main' updated 2021-12-13 11:03:33,913: DEBUG - Full log of this operation: 'Update URL related to permission 'rocketchat'' 2021-12-13 11:03:34,178: DEBUG - The permission database has been resynchronized 2021-12-13 11:03:34,342: DEBUG - SSOwat configuration regenerated 2021-12-13 11:03:34,473: DEBUG - Permission 'rocketchat.main' created 2021-12-13 11:03:34,474: DEBUG - Full log of this operation: 'Create permission 'rocketchat'' 2021-12-13 11:03:34,492: DEBUG - Executing command '['sh', '-c', '/bin/bash -x "./install" 7>&1']' 2021-12-13 11:03:34,503: DEBUG - + source _common.sh 2021-12-13 11:03:34,504: DEBUG - ++ nodejs_version=12 2021-12-13 11:03:34,504: DEBUG - ++ pkg_dependencies='apt-transport-https build-essential gzip curl fontconfig graphicsmagick' 2021-12-13 11:03:34,504: DEBUG - ++ MONGO_DEBIAN_SERVICENAME=mongodb 2021-12-13 11:03:34,504: DEBUG - ++ MONGO_CE_SERVICENAME=mongod 2021-12-13 11:03:34,504: DEBUG - ++ MONGO_DEBIAN_DEPENDENCIES='mongodb mongodb-server mongo-tools' 2021-12-13 11:03:34,504: DEBUG - ++ MONGO_CE_DEPENDENCIES='mongodb-org mongodb-org-server mongodb-org-tools' 2021-12-13 11:03:34,505: DEBUG - ++ MONGO_DEBIAN_CONFIG=/etc/mongodb.conf 2021-12-13 11:03:34,505: DEBUG - ++ MONGO_CE_CONFIG=/etc/mongod.conf 2021-12-13 11:03:34,505: DEBUG - ++ MONGO_CE_REPO='deb http://repo.mongodb.org/apt/debian buster/mongodb-org/5.0 main' 2021-12-13 11:03:34,505: DEBUG - ++ MONGO_CE_KEY=https://www.mongodb.org/static/pgp/server-5.0.asc 2021-12-13 11:03:34,505: DEBUG - + source /usr/share/yunohost/helpers 2021-12-13 11:03:34,506: DEBUG - +++ grep xtrace 2021-12-13 11:03:34,508: DEBUG - +++ set +o 2021-12-13 11:03:34,509: DEBUG - ++ readonly 'XTRACE_ENABLE=set -o xtrace' 2021-12-13 11:03:34,509: DEBUG - ++ XTRACE_ENABLE='set -o xtrace' 2021-12-13 11:03:34,546: DEBUG - + ynh_abort_if_errors 2021-12-13 11:03:34,546: DEBUG - + trap ynh_exit_properly EXIT 2021-12-13 11:03:34,547: DEBUG - + domain=chat.maindomain.tld 2021-12-13 11:03:34,547: DEBUG - + path_url=/ 2021-12-13 11:03:34,547: DEBUG - + is_public=0 2021-12-13 11:03:34,547: DEBUG - + password=** 2021-12-13 11:03:34,547: DEBUG - + admin=johns 2021-12-13 11:03:34,548: DEBUG - ++ ynh_user_get_info --username=johns --key=mail 2021-12-13 11:03:34,583: DEBUG - ++ jq -r .mail 2021-12-13 11:03:34,584: DEBUG - ++ yunohost user info johns --output-as json --quiet 2021-12-13 11:03:35,076: DEBUG - + email=johns@maindomain.tld 2021-12-13 11:03:35,076: DEBUG - + app=rocketchat 2021-12-13 11:03:35,169: DEBUG - + final_path=/var/www/rocketchat 2021-12-13 11:03:35,169: DEBUG - + test '!' -e /var/www/rocketchat 2021-12-13 11:03:35,169: DEBUG - + ynh_webpath_register --app=rocketchat --domain=chat.maindomain.tld --path_url=/ 2021-12-13 11:03:35,170: INFO - [....................] > Validating installation parameters... 2021-12-13 11:03:35,241: DEBUG - + yunohost app register-url rocketchat chat.maindomain.tld / 2021-12-13 11:03:36,982: DEBUG - + ynh_app_setting_set --app=rocketchat --key=domain --value=chat.maindomain.tld 2021-12-13 11:03:36,982: DEBUG - + local globalapp=rocketchat 2021-12-13 11:03:36,984: INFO - [....................] > Storing installation settings... 2021-12-13 11:03:37,063: DEBUG - + app=rocketchat 2021-12-13 11:03:37,063: DEBUG - + [[ domain =~ (unprotected|protected|skipped) ]] 2021-12-13 11:03:37,063: DEBUG - + ynh_app_setting set rocketchat domain chat.maindomain.tld 2021-12-13 11:03:37,121: DEBUG - + ynh_app_setting_set --app=rocketchat --key=path --value=/ 2021-12-13 11:03:37,122: DEBUG - + local globalapp=rocketchat 2021-12-13 11:03:37,191: DEBUG - + app=rocketchat 2021-12-13 11:03:37,192: DEBUG - + [[ path =~ (unprotected|protected|skipped) ]] 2021-12-13 11:03:37,192: DEBUG - + ynh_app_setting set rocketchat path / 2021-12-13 11:03:37,244: DEBUG - + ynh_app_setting_set --app=rocketchat --key=admin --value=johns 2021-12-13 11:03:37,244: DEBUG - + local globalapp=rocketchat 2021-12-13 11:03:37,312: DEBUG - + app=rocketchat 2021-12-13 11:03:37,312: DEBUG - + [[ admin =~ (unprotected|protected|skipped) ]] 2021-12-13 11:03:37,312: DEBUG - + ynh_app_setting set rocketchat admin johns 2021-12-13 11:03:37,370: DEBUG - + ynh_app_setting_set --app=rocketchat --key=password --value=** 2021-12-13 11:03:37,370: DEBUG - + local globalapp=rocketchat 2021-12-13 11:03:37,440: DEBUG - + app=rocketchat 2021-12-13 11:03:37,441: DEBUG - + [[ password =~ (unprotected|protected|skipped) ]] 2021-12-13 11:03:37,441: DEBUG - + ynh_app_setting set rocketchat password ** 2021-12-13 11:03:37,494: DEBUG - + ynh_app_setting_set --app=rocketchat --key=email --value=johns@maindomain.tld 2021-12-13 11:03:37,495: DEBUG - + local globalapp=rocketchat 2021-12-13 11:03:37,565: DEBUG - + app=rocketchat 2021-12-13 11:03:37,565: DEBUG - + [[ email =~ (unprotected|protected|skipped) ]] 2021-12-13 11:03:37,566: DEBUG - + ynh_app_setting set rocketchat email johns@maindomain.tld 2021-12-13 11:03:37,700: INFO - [+...................] > Finding an available port... 2021-12-13 11:03:37,701: DEBUG - ++ ynh_find_port --port=3000 2021-12-13 11:03:37,714: DEBUG - ++ test -n 3000 2021-12-13 11:03:37,715: DEBUG - ++ ynh_port_available --port=3000 2021-12-13 11:03:37,728: DEBUG - ++ grep --quiet --extended-regexp ':3000$' 2021-12-13 11:03:37,729: DEBUG - ++ awk '{print$5}' 2021-12-13 11:03:37,732: DEBUG - ++ ss --numeric --listening --tcp --udp 2021-12-13 11:03:37,743: DEBUG - ++ return 1 2021-12-13 11:03:37,743: DEBUG - ++ port=3001 2021-12-13 11:03:37,743: DEBUG - ++ ynh_port_available --port=3001 2021-12-13 11:03:37,756: DEBUG - ++ grep --quiet --extended-regexp ':3001$' 2021-12-13 11:03:37,757: DEBUG - ++ awk '{print$5}' 2021-12-13 11:03:37,761: DEBUG - ++ ss --numeric --listening --tcp --udp 2021-12-13 11:03:37,765: DEBUG - ++ grep -q 'port: '\''3001'\''' /etc/yunohost/apps/bookstack/settings.yml /etc/yunohost/apps/dokuwiki/settings.yml /etc/yunohost/apps/flarum/settings.yml /etc/yunohost/apps/hedgedoc/settings.yml /etc/yunohost/apps/kanboard/settings.yml /etc/yunohost/apps/mattermost/settings.yml /etc/yunohost/apps/nextcloud/settings.yml /etc/yunohost/apps/rainloop/settings.yml /etc/yunohost/apps/rocketchat/settings.yml /etc/yunohost/apps/synapse/settings.yml 2021-12-13 11:03:37,768: DEBUG - ++ return 0 2021-12-13 11:03:37,769: DEBUG - ++ echo 3001 2021-12-13 11:03:37,769: DEBUG - + port=3001 2021-12-13 11:03:37,769: DEBUG - + ynh_app_setting_set --app=rocketchat --key=port --value=3001 2021-12-13 11:03:37,769: DEBUG - + local globalapp=rocketchat 2021-12-13 11:03:37,845: DEBUG - + app=rocketchat 2021-12-13 11:03:37,845: DEBUG - + [[ port =~ (unprotected|protected|skipped) ]] 2021-12-13 11:03:37,845: DEBUG - + ynh_app_setting set rocketchat port 3001 2021-12-13 11:03:37,976: DEBUG - + ynh_install_app_dependencies apt-transport-https build-essential gzip curl fontconfig graphicsmagick 2021-12-13 11:03:37,977: DEBUG - + local 'dependencies=apt-transport-https build-essential gzip curl fontconfig graphicsmagick' 2021-12-13 11:03:37,977: INFO - [#++++++.............] > Installing dependencies... 2021-12-13 11:03:37,978: DEBUG - ++ sed 's/([^\<=>])\ ([^(])/\1, \2/g' 2021-12-13 11:03:37,981: DEBUG - ++ echo 'apt-transport-https build-essential gzip curl fontconfig graphicsmagick' 2021-12-13 11:03:37,982: DEBUG - + dependencies='apt-transport-https, build-essential, gzip, curl, fontconfig, graphicsmagick' 2021-12-13 11:03:37,982: DEBUG - + local 'dependencies=apt-transport-https, build-essential, gzip, curl, fontconfig, graphicsmagick' 2021-12-13 11:03:37,983: DEBUG - + local manifest_path=/var/cache/yunohost/app_tmp_work_dirs/app_55je6c1e/manifest.json 2021-12-13 11:03:37,983: DEBUG - ++ jq -r .version /var/cache/yunohost/app_tmp_work_dirs/app_55je6c1e/manifest.json 2021-12-13 11:03:37,988: DEBUG - + local version=4.2.1~ynh1 2021-12-13 11:03:37,988: DEBUG - + '[' -z 4.2.1~ynh1 ']' 2021-12-13 11:03:37,988: DEBUG - + '[' 4.2.1~ynh1 == null ']' 2021-12-13 11:03:37,989: DEBUG - + local dep_app=rocketchat 2021-12-13 11:03:37,989: DEBUG - + [[ apt-transport-https, build-essential, gzip, curl, fontconfig, graphicsmagick =~ [<=>] ]] 2021-12-13 11:03:37,990: DEBUG - ++ sort -u 2021-12-13 11:03:37,992: DEBUG - ++ grep -oP '(?<=php)[0-9.]+(?=-|>)' 2021-12-13 11:03:37,993: DEBUG - ++ echo apt-transport-https, build-essential, gzip, curl, fontconfig, graphicsmagick 2021-12-13 11:03:37,995: DEBUG - + local specific_php_version= 2021-12-13 11:03:37,995: DEBUG - + [[ '' != \7.\3 ]] 2021-12-13 11:03:37,995: DEBUG - + [[ true == \t\r\u\e ]] 2021-12-13 11:03:37,996: DEBUG - + YNH_INSTALL_APP_DEPENDENCIES_REPLACE=false 2021-12-13 11:03:37,996: DEBUG - + grep --quiet php 2021-12-13 11:03:37,998: DEBUG - + cat 2021-12-13 11:03:38,000: DEBUG - + ynh_package_install_from_equivs /tmp/rocketchat-ynh-deps.control 2021-12-13 11:03:38,000: DEBUG - + local controlfile=/tmp/rocketchat-ynh-deps.control 2021-12-13 11:03:38,001: DEBUG - ++ cut '--delimiter= ' --fields=2 2021-12-13 11:03:38,003: DEBUG - ++ grep '^Package: ' /tmp/rocketchat-ynh-deps.control 2021-12-13 11:03:38,005: DEBUG - + local pkgname=rocketchat-ynh-deps 2021-12-13 11:03:38,006: DEBUG - ++ cut '--delimiter= ' --fields=2 2021-12-13 11:03:38,008: DEBUG - ++ grep '^Version: ' /tmp/rocketchat-ynh-deps.control 2021-12-13 11:03:38,010: DEBUG - + local pkgversion=4.2.1~ynh1 2021-12-13 11:03:38,010: DEBUG - + [[ -z rocketchat-ynh-deps ]] 2021-12-13 11:03:38,011: DEBUG - + [[ -z 4.2.1~ynh1 ]] 2021-12-13 11:03:38,011: DEBUG - + ynh_package_update 2021-12-13 11:03:38,011: DEBUG - + ynh_apt update 2021-12-13 11:03:38,011: DEBUG - + ynh_wait_dpkg_free 2021-12-13 11:03:38,167: DEBUG - + return 0 2021-12-13 11:03:38,168: DEBUG - + LC_ALL=C 2021-12-13 11:03:38,168: DEBUG - + DEBIAN_FRONTEND=noninteractive 2021-12-13 11:03:38,168: DEBUG - + apt-get --assume-yes --quiet -o=Acquire::Retries=3 -o=Dpkg::Use-Pty=0 update 2021-12-13 11:03:38,433: DEBUG - Hit:1 http://deb.debian.org/debian buster InRelease 2021-12-13 11:03:38,434: DEBUG - Hit:2 http://security.debian.org/debian-security buster/updates InRelease 2021-12-13 11:03:38,434: DEBUG - Hit:3 http://forge.yunohost.org/debian buster InRelease 2021-12-13 11:03:39,076: DEBUG - Hit:4 https://collaboraoffice.com/repos/CollaboraOnline/CODE-debian10 ./ InRelease 2021-12-13 11:03:40,282: DEBUG - Reading package lists... 2021-12-13 11:03:40,555: DEBUG - ++ mktemp --directory 2021-12-13 11:03:40,560: DEBUG - + local TMPDIR=/tmp/tmp.aeVA23nJ9U 2021-12-13 11:03:40,560: DEBUG - + echo 10 2021-12-13 11:03:40,562: DEBUG - + ynh_wait_dpkg_free 2021-12-13 11:03:40,725: DEBUG - + return 0 2021-12-13 11:03:40,726: DEBUG - + cp /tmp/rocketchat-ynh-deps.control /tmp/tmp.aeVA23nJ9U/control 2021-12-13 11:03:40,729: DEBUG - + cd /tmp/tmp.aeVA23nJ9U 2021-12-13 11:03:40,729: DEBUG - + LC_ALL=C 2021-12-13 11:03:40,729: DEBUG - + equivs-build ./control 2021-12-13 11:03:41,714: DEBUG - + tee ./dpkg_log 2021-12-13 11:03:41,715: DEBUG - + LC_ALL=C 2021-12-13 11:03:41,716: DEBUG - + dpkg --force-depends --install ./rocketchat-ynh-deps_4.2.1~ynh1_all.deb 2021-12-13 11:03:41,758: DEBUG - Selecting previously unselected package rocketchat-ynh-deps. 2021-12-13 11:03:41,971: DEBUG - (Reading database ... 64100 files and directories currently installed.) 2021-12-13 11:03:41,975: DEBUG - Preparing to unpack .../rocketchat-ynh-deps_4.2.1~ynh1_all.deb ... 2021-12-13 11:03:41,978: DEBUG - Unpacking rocketchat-ynh-deps (4.2.1~ynh1) ... 2021-12-13 11:03:42,004: DEBUG - dpkg: rocketchat-ynh-deps: dependency problems, but configuring anyway as you requested: 2021-12-13 11:03:42,004: DEBUG - rocketchat-ynh-deps depends on graphicsmagick; however: 2021-12-13 11:03:42,004: DEBUG - Package graphicsmagick is not installed. 2021-12-13 11:03:42,004: DEBUG - 2021-12-13 11:03:42,004: DEBUG - Setting up rocketchat-ynh-deps (4.2.1~ynh1) ... 2021-12-13 11:03:42,023: DEBUG - + ynh_package_install --fix-broken 2021-12-13 11:03:42,023: DEBUG - + ynh_apt --no-remove --option Dpkg::Options::=--force-confdef --option Dpkg::Options::=--force-confold install --fix-broken 2021-12-13 11:03:42,024: DEBUG - + ynh_wait_dpkg_free 2021-12-13 11:03:42,176: DEBUG - + return 0 2021-12-13 11:03:42,176: DEBUG - + LC_ALL=C 2021-12-13 11:03:42,176: DEBUG - + DEBIAN_FRONTEND=noninteractive 2021-12-13 11:03:42,176: DEBUG - + apt-get --assume-yes --quiet -o=Acquire::Retries=3 -o=Dpkg::Use-Pty=0 --no-remove --option Dpkg::Options::=--force-confdef --option Dpkg::Options::=--force-confold install --fix-broken 2021-12-13 11:03:42,404: DEBUG - Reading package lists... 2021-12-13 11:03:42,682: DEBUG - Building dependency tree... 2021-12-13 11:03:42,684: DEBUG - Reading state information... 2021-12-13 11:03:42,788: DEBUG - Correcting dependencies... Done 2021-12-13 11:03:42,944: DEBUG - The following additional packages will be installed: 2021-12-13 11:03:42,945: DEBUG - graphicsmagick libgraphicsmagick-q16-3 libice6 libsm6 x11-common 2021-12-13 11:03:42,948: DEBUG - Suggested packages: 2021-12-13 11:03:42,948: DEBUG - graphicsmagick-dbg 2021-12-13 11:03:42,971: DEBUG - The following NEW packages will be installed: 2021-12-13 11:03:42,972: DEBUG - graphicsmagick libgraphicsmagick-q16-3 libice6 libsm6 x11-common 2021-12-13 11:03:43,461: DEBUG - 0 upgraded, 5 newly installed, 0 to remove and 0 not upgraded. 2021-12-13 11:03:43,462: DEBUG - Need to get 0 B/2487 kB of archives. 2021-12-13 11:03:43,462: DEBUG - After this operation, 9089 kB of additional disk space will be used. 2021-12-13 11:03:43,491: DEBUG - Selecting previously unselected package x11-common. 2021-12-13 11:03:43,543: DEBUG - (Reading database ... 64104 files and directories currently installed.) 2021-12-13 11:03:43,547: DEBUG - Preparing to unpack .../x11-common_1%3a7.7+19_all.deb ... 2021-12-13 11:03:43,548: DEBUG - Unpacking x11-common (1:7.7+19) ... 2021-12-13 11:03:43,595: DEBUG - Selecting previously unselected package libice6:amd64. 2021-12-13 11:03:43,604: DEBUG - Preparing to unpack .../libice6_2%3a1.0.9-2_amd64.deb ... 2021-12-13 11:03:43,607: DEBUG - Unpacking libice6:amd64 (2:1.0.9-2) ... 2021-12-13 11:03:43,634: DEBUG - Selecting previously unselected package libsm6:amd64. 2021-12-13 11:03:43,643: DEBUG - Preparing to unpack .../libsm6_2%3a1.2.3-1_amd64.deb ... 2021-12-13 11:03:43,644: DEBUG - Unpacking libsm6:amd64 (2:1.2.3-1) ... 2021-12-13 11:03:43,670: DEBUG - Selecting previously unselected package libgraphicsmagick-q16-3. 2021-12-13 11:03:43,679: DEBUG - Preparing to unpack .../libgraphicsmagick-q16-3_1.4+really1.3.35-1~deb10u1_amd64.deb ... 2021-12-13 11:03:43,681: DEBUG - Unpacking libgraphicsmagick-q16-3 (1.4+really1.3.35-1~deb10u1) ... 2021-12-13 11:03:43,853: DEBUG - Selecting previously unselected package graphicsmagick. 2021-12-13 11:03:43,862: DEBUG - Preparing to unpack .../graphicsmagick_1.4+really1.3.35-1~deb10u1_amd64.deb ... 2021-12-13 11:03:43,864: DEBUG - Unpacking graphicsmagick (1.4+really1.3.35-1~deb10u1) ... 2021-12-13 11:03:44,083: DEBUG - Setting up x11-common (1:7.7+19) ... 2021-12-13 11:03:44,106: DEBUG - /bin/bash: BASH_XTRACEFD: 7: invalid value for trace file descriptor 2021-12-13 11:03:44,254: DEBUG - /bin/bash: BASH_XTRACEFD: 7: invalid value for trace file descriptor 2021-12-13 11:03:44,274: DEBUG - update-rc.d: warning: start and stop actions are no longer supported; falling back to defaults 2021-12-13 11:03:45,045: DEBUG - Setting up libice6:amd64 (2:1.0.9-2) ... 2021-12-13 11:03:45,048: DEBUG - Setting up libsm6:amd64 (2:1.2.3-1) ... 2021-12-13 11:03:45,052: DEBUG - Setting up libgraphicsmagick-q16-3 (1.4+really1.3.35-1~deb10u1) ... 2021-12-13 11:03:45,055: DEBUG - Setting up graphicsmagick (1.4+really1.3.35-1~deb10u1) ... 2021-12-13 11:03:45,068: DEBUG - Processing triggers for systemd (241-7~deb10u8) ... 2021-12-13 11:03:45,388: DEBUG - Processing triggers for man-db (2.8.5-2) ... 2021-12-13 11:03:45,890: DEBUG - Processing triggers for mime-support (3.62) ... 2021-12-13 11:03:45,919: DEBUG - Processing triggers for libc-bin (2.28-10) ... 2021-12-13 11:03:46,132: DEBUG - + [[ -n /tmp/tmp.aeVA23nJ9U ]] 2021-12-13 11:03:46,132: DEBUG - + rm --recursive --force /tmp/tmp.aeVA23nJ9U 2021-12-13 11:03:46,134: DEBUG - + ynh_package_is_installed rocketchat-ynh-deps 2021-12-13 11:03:46,146: DEBUG - + ynh_wait_dpkg_free 2021-12-13 11:03:46,300: DEBUG - + return 0 2021-12-13 11:03:46,300: DEBUG - + grep --count 'ok installed' 2021-12-13 11:03:46,302: DEBUG - + dpkg-query --show '--showformat=${Status}' rocketchat-ynh-deps 2021-12-13 11:03:46,331: DEBUG - + rm /tmp/rocketchat-ynh-deps.control 2021-12-13 11:03:46,334: DEBUG - + grep --quiet php 2021-12-13 11:03:46,337: DEBUG - + ynh_exec_warn_less ynh_install_nodejs --nodejs_version=12 2021-12-13 11:03:46,338: DEBUG - + [[ 2 -eq 1 ]] 2021-12-13 11:03:46,338: DEBUG - + ynh_install_nodejs --nodejs_version=12 2021-12-13 11:03:46,351: DEBUG - + mkdir --parents /opt/node_n 2021-12-13 11:03:46,353: DEBUG - + CLEAR_PATH=/opt/node_n/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin 2021-12-13 11:03:46,354: DEBUG - ++ sed s@/usr/local/bin:@@ 2021-12-13 11:03:46,356: DEBUG - ++ echo /opt/node_n/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin 2021-12-13 11:03:46,358: DEBUG - + PATH=/opt/node_n/bin:/usr/local/sbin:/usr/sbin:/usr/bin:/sbin:/bin 2021-12-13 11:03:46,358: DEBUG - + test -x /usr/bin/node 2021-12-13 11:03:46,358: DEBUG - + mv /usr/bin/node /usr/bin/node_n 2021-12-13 11:03:46,360: DEBUG - + test -x /usr/bin/npm 2021-12-13 11:03:46,360: DEBUG - + /opt/node_n/bin/n --version 2021-12-13 11:03:46,371: DEBUG - ++ /opt/node_n/bin/n --version 2021-12-13 11:03:46,381: DEBUG - + dpkg --compare-versions v8.0.0 lt 8.0.1 2021-12-13 11:03:46,384: DEBUG - dpkg: warning: version 'v8.0.0' has bad syntax: version number does not start with digit 2021-12-13 11:03:46,385: DEBUG - + ynh_replace_string '--match_string=^N_PREFIX=${N_PREFIX-.}$' '--replace_string=N_PREFIX=${N_PREFIX-/opt/node_n}' --target_file=/opt/node_n/bin/n 2021-12-13 11:03:46,455: DEBUG - + sed --in-place 's@^N_PREFIX=${N_PREFIX-.}$@N_PREFIX=${N_PREFIX-/opt/node_n}@g' /opt/node_n/bin/n 2021-12-13 11:03:46,458: DEBUG - + PATH=/opt/node_n/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin 2021-12-13 11:03:46,458: DEBUG - + test -x /usr/bin/node_n 2021-12-13 11:03:46,458: DEBUG - + mv /usr/bin/node_n /usr/bin/node 2021-12-13 11:03:46,460: DEBUG - + test -x /usr/bin/npm_n 2021-12-13 11:03:46,460: DEBUG - ++ uname --machine 2021-12-13 11:03:46,462: DEBUG - + uname=x86_64 2021-12-13 11:03:46,463: DEBUG - + [[ x86_64 =~ aarch64 ]] 2021-12-13 11:03:46,463: DEBUG - + [[ x86_64 =~ arm64 ]] 2021-12-13 11:03:46,463: DEBUG - + n 12 2021-12-13 11:03:46,603: DEBUG - installing : node-v12.22.7 2021-12-13 11:03:46,791: DEBUG - mkdir : /opt/node_n/n/versions/node/12.22.7 2021-12-13 11:03:46,795: DEBUG - fetch : https://nodejs.org/dist/v12.22.7/node-v12.22.7-linux-x64.tar.xz 2021-12-13 11:03:50,921: DEBUG - installed : v12.22.7 (with npm 6.14.15) 2021-12-13 11:03:50,923: DEBUG - ++ tail --lines=1 2021-12-13 11:03:50,924: DEBUG - ++ sort --version-sort 2021-12-13 11:03:50,926: DEBUG - ++ find /opt/node_n/n/versions/node/12 /opt/node_n/n/versions/node/12.22.7 -maxdepth 0 2021-12-13 11:03:50,929: DEBUG - + real_nodejs_version=/opt/node_n/n/versions/node/12.22.7 2021-12-13 11:03:50,930: DEBUG - ++ basename /opt/node_n/n/versions/node/12.22.7 2021-12-13 11:03:50,931: DEBUG - + real_nodejs_version=12.22.7 2021-12-13 11:03:50,932: DEBUG - + '[' '!' -e /opt/node_n/n/versions/node/12 ']' 2021-12-13 11:03:50,932: DEBUG - + tee --append /opt/node_n/ynh_app_version 2021-12-13 11:03:50,933: DEBUG - + echo rocketchat:12 2021-12-13 11:03:50,935: DEBUG - rocketchat:12 2021-12-13 11:03:50,936: DEBUG - + ynh_app_setting_set --app=rocketchat --key=nodejs_version --value=12 2021-12-13 11:03:50,936: DEBUG - + local _globalapp=rocketchat 2021-12-13 11:03:51,008: DEBUG - + app=rocketchat 2021-12-13 11:03:51,008: DEBUG - + [[ nodejsversion =~ (unprotected|protected|skipped) ]] 2021-12-13 11:03:51,008: DEBUG - + ynh_app_setting set rocketchat nodejs_version 12 2021-12-13 11:03:51,098: DEBUG - + ynh_cron_upgrade_node 2021-12-13 11:03:51,098: DEBUG - + cat 2021-12-13 11:03:51,100: DEBUG - + chmod +x /opt/node_n/node_update.sh 2021-12-13 11:03:51,102: DEBUG - + cat 2021-12-13 11:03:51,104: DEBUG - + chmod +x /etc/cron.daily/node_update 2021-12-13 11:03:51,105: DEBUG - + ynh_use_nodejs 2021-12-13 11:03:51,106: DEBUG - ++ ynh_app_setting_get --app=rocketchat --key=nodejs_version 2021-12-13 11:03:51,106: DEBUG - ++ local _globalapp=rocketchat 2021-12-13 11:03:51,140: DEBUG - ++ app=rocketchat 2021-12-13 11:03:51,141: DEBUG - ++ [[ nodejsversion =~ (unprotected|protected|skipped) ]] 2021-12-13 11:03:51,141: DEBUG - ++ ynh_app_setting get rocketchat nodejs_version 2021-12-13 11:03:51,193: DEBUG - + nodejs_version=12 2021-12-13 11:03:51,193: DEBUG - + nodejs_path=/opt/node_n/n/versions/node/12/bin 2021-12-13 11:03:51,193: DEBUG - + shopt -s expand_aliases 2021-12-13 11:03:51,193: DEBUG - + ynh_node=/opt/node_n/n/versions/node/12/bin/node 2021-12-13 11:03:51,193: DEBUG - + alias ynh_node=/opt/node_n/n/versions/node/12/bin/node 2021-12-13 11:03:51,194: DEBUG - + ynh_npm=/opt/node_n/n/versions/node/12/bin/npm 2021-12-13 11:03:51,194: DEBUG - + alias ynh_npm=/opt/node_n/n/versions/node/12/bin/npm 2021-12-13 11:03:51,194: DEBUG - + [[ :/opt/noden/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin: != *\:\/\o\p\t\/\n\o\d\e\\n\/\n\/\v\e\r\s\i\o\n\s\/\n\o\d\e\/\1\2\/\b\i\n ]] 2021-12-13 11:03:51,194: DEBUG - + PATH=/opt/node_n/n/versions/node/12/bin:/opt/node_n/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin 2021-12-13 11:03:51,194: DEBUG - + node_PATH=/opt/node_n/n/versions/node/12/bin:/opt/node_n/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin 2021-12-13 11:03:51,194: DEBUG - + ynh_node_load_PATH=PATH=/opt/node_n/n/versions/node/12/bin:/opt/node_n/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin 2021-12-13 11:03:51,194: DEBUG - + ynh_node_load_path=PATH=/opt/node_n/n/versions/node/12/bin:/opt/node_n/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin 2021-12-13 11:03:51,194: DEBUG - + ynh_install_mongo 2021-12-13 11:03:51,272: INFO - [#######++...........] > Installing MongoDB... 2021-12-13 11:03:51,274: DEBUG - +++ cat /etc/debian_version 2021-12-13 11:03:51,277: DEBUG - ++ dpkg --compare-versions 10.11 gt 10.0 2021-12-13 11:03:51,280: DEBUG - + ynh_install_extra_app_dependencies '--repo=deb http://repo.mongodb.org/apt/debian buster/mongodb-org/5.0 main' '--package=mongodb-org mongodb-org-server mongodb-org-tools' --key=https://www.mongodb.org/static/pgp/server-5.0.asc 2021-12-13 11:03:51,383: DEBUG - + name=rocketchat 2021-12-13 11:03:51,384: DEBUG - + key=https://www.mongodb.org/static/pgp/server-5.0.asc 2021-12-13 11:03:51,384: DEBUG - + '[' -n https://www.mongodb.org/static/pgp/server-5.0.asc ']' 2021-12-13 11:03:51,384: DEBUG - + key=--key=https://www.mongodb.org/static/pgp/server-5.0.asc 2021-12-13 11:03:51,384: DEBUG - + ynh_install_extra_repo '--repo=deb http://repo.mongodb.org/apt/debian buster/mongodb-org/5.0 main' --key=https://www.mongodb.org/static/pgp/server-5.0.asc --priority=995 --name=rocketchat 2021-12-13 11:03:51,537: DEBUG - + name=rocketchat 2021-12-13 11:03:51,537: DEBUG - + append=0 2021-12-13 11:03:51,537: DEBUG - + key=https://www.mongodb.org/static/pgp/server-5.0.asc 2021-12-13 11:03:51,537: DEBUG - + priority=995 2021-12-13 11:03:51,537: DEBUG - + append= 2021-12-13 11:03:51,537: DEBUG - + wget_append=tee 2021-12-13 11:03:51,538: DEBUG - + repo='http://repo.mongodb.org/apt/debian buster/mongodb-org/5.0 main' 2021-12-13 11:03:51,539: DEBUG - ++ awk '{ print $1 }' 2021-12-13 11:03:51,540: DEBUG - ++ echo 'http://repo.mongodb.org/apt/debian buster/mongodb-org/5.0 main' 2021-12-13 11:03:51,546: DEBUG - + local uri=http://repo.mongodb.org/apt/debian 2021-12-13 11:03:51,547: DEBUG - ++ awk '{ print $2 }' 2021-12-13 11:03:51,549: DEBUG - ++ echo 'http://repo.mongodb.org/apt/debian buster/mongodb-org/5.0 main' 2021-12-13 11:03:51,552: DEBUG - + local suite=buster/mongodb-org/5.0 2021-12-13 11:03:51,552: DEBUG - + local component=main 2021-12-13 11:03:51,552: DEBUG - + ynh_add_repo --uri=http://repo.mongodb.org/apt/debian --suite=buster/mongodb-org/5.0 --component=main --name=rocketchat 2021-12-13 11:03:51,705: DEBUG - + name=rocketchat 2021-12-13 11:03:51,706: DEBUG - + append=0 2021-12-13 11:03:51,706: DEBUG - + append=tee 2021-12-13 11:03:51,706: DEBUG - + mkdir --parents /etc/apt/sources.list.d 2021-12-13 11:03:51,708: DEBUG - + tee /etc/apt/sources.list.d/rocketchat.list 2021-12-13 11:03:51,710: DEBUG - deb http://repo.mongodb.org/apt/debian buster/mongodb-org/5.0 main 2021-12-13 11:03:51,711: DEBUG - + local pin=repo.mongodb.org/apt/debian 2021-12-13 11:03:51,711: DEBUG - + pin=repo.mongodb.org 2021-12-13 11:03:51,712: DEBUG - + '[' -n 995 ']' 2021-12-13 11:03:51,712: DEBUG - + priority=--priority=995 2021-12-13 11:03:51,712: DEBUG - + ynh_pin_repo '--package=' '--pin=origin "repo.mongodb.org"' --priority=995 --name=rocketchat 2021-12-13 11:03:51,865: DEBUG - + package='' 2021-12-13 11:03:51,865: DEBUG - + priority=995 2021-12-13 11:03:51,865: DEBUG - + name=rocketchat 2021-12-13 11:03:51,865: DEBUG - + append=0 2021-12-13 11:03:51,865: DEBUG - + append=tee 2021-12-13 11:03:51,865: DEBUG - + [[ rocketchat != \e\x\t\r\a_\p\h\p_\v\e\r\s\i\o\n ]] 2021-12-13 11:03:51,865: DEBUG - + mkdir --parents /etc/apt/preferences.d 2021-12-13 11:03:51,867: DEBUG - + tee /etc/apt/preferences.d/rocketchat 2021-12-13 11:03:51,869: DEBUG - Pin: origin "repo.mongodb.org" 2021-12-13 11:03:51,869: DEBUG - Pin-Priority: 995 2021-12-13 11:03:51,869: DEBUG - ' 2021-12-13 11:03:51,870: DEBUG - Package: 2021-12-13 11:03:51,870: DEBUG - Pin: origin "repo.mongodb.org" 2021-12-13 11:03:51,870: DEBUG - Pin-Priority: 995 2021-12-13 11:03:51,870: DEBUG - 2021-12-13 11:03:51,871: DEBUG - + '[' -n https://www.mongodb.org/static/pgp/server-5.0.asc ']' 2021-12-13 11:03:51,871: DEBUG - + mkdir --parents /etc/apt/trusted.gpg.d 2021-12-13 11:03:51,873: DEBUG - + tee /etc/apt/trusted.gpg.d/rocketchat.gpg 2021-12-13 11:03:51,875: DEBUG - + gpg --dearmor 2021-12-13 11:03:51,876: DEBUG - + wget --timeout 900 --quiet https://www.mongodb.org/static/pgp/server-5.0.asc --output-document=- 2021-12-13 11:03:52,469: DEBUG - + ynh_package_update 2021-12-13 11:03:52,470: DEBUG - + ynh_apt update 2021-12-13 11:03:52,470: DEBUG - + ynh_wait_dpkg_free 2021-12-13 11:03:52,639: DEBUG - + return 0 2021-12-13 11:03:52,640: DEBUG - + LC_ALL=C 2021-12-13 11:03:52,640: DEBUG - + DEBIAN_FRONTEND=noninteractive 2021-12-13 11:03:52,640: DEBUG - + apt-get --assume-yes --quiet -o=Acquire::Retries=3 -o=Dpkg::Use-Pty=0 update 2021-12-13 11:03:52,875: DEBUG - Hit:1 http://forge.yunohost.org/debian buster InRelease 2021-12-13 11:03:52,905: DEBUG - Hit:2 http://security.debian.org/debian-security buster/updates InRelease 2021-12-13 11:03:52,905: DEBUG - Hit:3 http://deb.debian.org/debian buster InRelease 2021-12-13 11:03:53,076: DEBUG - Ign:4 http://repo.mongodb.org/apt/debian buster/mongodb-org/5.0 InRelease 2021-12-13 11:03:53,244: DEBUG - Get:6 http://repo.mongodb.org/apt/debian buster/mongodb-org/5.0 Release [2396 B] 2021-12-13 11:03:53,502: DEBUG - Get:7 http://repo.mongodb.org/apt/debian buster/mongodb-org/5.0 Release.gpg [801 B] 2021-12-13 11:03:53,677: DEBUG - Hit:5 https://collaboraoffice.com/repos/CollaboraOnline/CODE-debian10 ./ InRelease 2021-12-13 11:03:53,811: DEBUG - Get:8 http://repo.mongodb.org/apt/debian buster/mongodb-org/5.0/main amd64 Packages [10.6 kB] 2021-12-13 11:03:53,834: DEBUG - Fetched 13.8 kB in 1s (12.5 kB/s) 2021-12-13 11:03:54,957: DEBUG - Reading package lists... 2021-12-13 11:03:55,017: DEBUG - + ynh_install_app_dependencies 'mongodb-org mongodb-org-server mongodb-org-tools' 2021-12-13 11:03:55,018: DEBUG - + local 'dependencies=mongodb-org mongodb-org-server mongodb-org-tools' 2021-12-13 11:03:55,019: DEBUG - ++ sed 's/([^\<=>])\ ([^(])/\1, \2/g' 2021-12-13 11:03:55,021: DEBUG - ++ echo 'mongodb-org mongodb-org-server mongodb-org-tools' 2021-12-13 11:03:55,114: DEBUG - + dependencies='mongodb-org, mongodb-org-server, mongodb-org-tools' 2021-12-13 11:03:55,114: DEBUG - + local 'dependencies=mongodb-org, mongodb-org-server, mongodb-org-tools' 2021-12-13 11:03:55,115: DEBUG - + local manifest_path=/var/cache/yunohost/app_tmp_work_dirs/app_55je6c1e/manifest.json 2021-12-13 11:03:55,115: DEBUG - ++ jq -r .version /var/cache/yunohost/app_tmp_work_dirs/app_55je6c1e/manifest.json 2021-12-13 11:03:55,261: DEBUG - + local version=4.2.1~ynh1 2021-12-13 11:03:55,261: DEBUG - + '[' -z 4.2.1~ynh1 ']' 2021-12-13 11:03:55,261: DEBUG - + '[' 4.2.1~ynh1 == null ']' 2021-12-13 11:03:55,261: DEBUG - + local dep_app=rocketchat 2021-12-13 11:03:55,261: DEBUG - + [[ mongodb-org, mongodb-org-server, mongodb-org-tools =~ [<=>] ]] 2021-12-13 11:03:55,263: DEBUG - ++ sort -u 2021-12-13 11:03:55,263: DEBUG - ++ grep -oP '(?<=php)[0-9.]+(?=-|>)' 2021-12-13 11:03:55,267: DEBUG - ++ echo mongodb-org, mongodb-org-server, mongodb-org-tools 2021-12-13 11:03:55,269: DEBUG - + local specific_php_version= 2021-12-13 11:03:55,269: DEBUG - + [[ '' != \7.\3 ]] 2021-12-13 11:03:55,269: DEBUG - + [[ false == \t\r\u\e ]] 2021-12-13 11:03:55,269: DEBUG - + local current_dependencies= 2021-12-13 11:03:55,269: DEBUG - + ynh_package_is_installed --package=rocketchat-ynh-deps 2021-12-13 11:03:55,281: DEBUG - + ynh_wait_dpkg_free 2021-12-13 11:03:55,429: DEBUG - + return 0 2021-12-13 11:03:55,430: DEBUG - + grep --count 'ok installed' 2021-12-13 11:03:55,432: DEBUG - + dpkg-query --show '--showformat=${Status}' rocketchat-ynh-deps 2021-12-13 11:03:55,452: DEBUG - ++ dpkg-query --show '--showformat=${Depends}' rocketchat-ynh-deps 2021-12-13 11:03:55,470: DEBUG - + current_dependencies='apt-transport-https, build-essential, gzip, curl, fontconfig, graphicsmagick ' 2021-12-13 11:03:55,470: DEBUG - + current_dependencies='apt-transport-https, build-essential, gzip, curl, fontconfig, graphicsmagick ' 2021-12-13 11:03:55,470: DEBUG - + dependencies='apt-transport-https, build-essential, gzip, curl, fontconfig, graphicsmagick , mongodb-org, mongodb-org-server, mongodb-org-tools' 2021-12-13 11:03:55,470: DEBUG - + grep --quiet php 2021-12-13 11:03:55,473: DEBUG - + cat 2021-12-13 11:03:55,475: DEBUG - + ynh_package_install_from_equivs /tmp/rocketchat-ynh-deps.control 2021-12-13 11:03:55,475: DEBUG - + local controlfile=/tmp/rocketchat-ynh-deps.control 2021-12-13 11:03:55,476: DEBUG - ++ cut '--delimiter= ' --fields=2 2021-12-13 11:03:55,478: DEBUG - ++ grep '^Package: ' /tmp/rocketchat-ynh-deps.control 2021-12-13 11:03:55,480: DEBUG - + local pkgname=rocketchat-ynh-deps 2021-12-13 11:03:55,481: DEBUG - ++ cut '--delimiter= ' --fields=2 2021-12-13 11:03:55,483: DEBUG - ++ grep '^Version: ' /tmp/rocketchat-ynh-deps.control 2021-12-13 11:03:55,485: DEBUG - + local pkgversion=4.2.1~ynh1 2021-12-13 11:03:55,485: DEBUG - + [[ -z rocketchat-ynh-deps ]] 2021-12-13 11:03:55,485: DEBUG - + [[ -z 4.2.1~ynh1 ]] 2021-12-13 11:03:55,485: DEBUG - + ynh_package_update 2021-12-13 11:03:55,485: DEBUG - + ynh_apt update 2021-12-13 11:03:55,486: DEBUG - + ynh_wait_dpkg_free 2021-12-13 11:03:55,636: DEBUG - + return 0 2021-12-13 11:03:55,636: DEBUG - + LC_ALL=C 2021-12-13 11:03:55,636: DEBUG - + DEBIAN_FRONTEND=noninteractive 2021-12-13 11:03:55,636: DEBUG - + apt-get --assume-yes --quiet -o=Acquire::Retries=3 -o=Dpkg::Use-Pty=0 update 2021-12-13 11:03:55,859: DEBUG - Hit:1 http://forge.yunohost.org/debian buster InRelease 2021-12-13 11:03:55,859: DEBUG - Ign:2 http://repo.mongodb.org/apt/debian buster/mongodb-org/5.0 InRelease 2021-12-13 11:03:55,908: DEBUG - Hit:3 http://repo.mongodb.org/apt/debian buster/mongodb-org/5.0 Release 2021-12-13 11:03:55,920: DEBUG - Hit:4 http://security.debian.org/debian-security buster/updates InRelease 2021-12-13 11:03:55,921: DEBUG - Hit:5 http://deb.debian.org/debian buster InRelease 2021-12-13 11:03:56,258: DEBUG - Hit:6 https://collaboraoffice.com/repos/CollaboraOnline/CODE-debian10 ./ InRelease 2021-12-13 11:03:57,565: DEBUG - Reading package lists... 2021-12-13 11:03:57,625: DEBUG - ++ mktemp --directory 2021-12-13 11:03:57,627: DEBUG - + local TMPDIR=/tmp/tmp.LFAgu0mYVY 2021-12-13 11:03:57,627: DEBUG - + echo 10 2021-12-13 11:03:57,648: DEBUG - + ynh_wait_dpkg_free 2021-12-13 11:03:57,800: DEBUG - + return 0 2021-12-13 11:03:57,800: DEBUG - + cp /tmp/rocketchat-ynh-deps.control /tmp/tmp.LFAgu0mYVY/control 2021-12-13 11:03:57,802: DEBUG - + cd /tmp/tmp.LFAgu0mYVY 2021-12-13 11:03:57,803: DEBUG - + LC_ALL=C 2021-12-13 11:03:57,803: DEBUG - + equivs-build ./control 2021-12-13 11:03:58,834: DEBUG - + tee ./dpkg_log 2021-12-13 11:03:58,836: DEBUG - + LC_ALL=C 2021-12-13 11:03:58,836: DEBUG - + dpkg --force-depends --install ./rocketchat-ynh-deps_4.2.1~ynh1_all.deb 2021-12-13 11:03:59,139: DEBUG - (Reading database ... 64284 files and directories currently installed.) 2021-12-13 11:03:59,142: DEBUG - Preparing to unpack .../rocketchat-ynh-deps_4.2.1~ynh1_all.deb ... 2021-12-13 11:03:59,145: DEBUG - Unpacking rocketchat-ynh-deps (4.2.1~ynh1) over (4.2.1~ynh1) ... 2021-12-13 11:03:59,170: DEBUG - dpkg: rocketchat-ynh-deps: dependency problems, but configuring anyway as you requested: 2021-12-13 11:03:59,170: DEBUG - rocketchat-ynh-deps depends on mongodb-org; however: 2021-12-13 11:03:59,170: DEBUG - Package mongodb-org is not installed. 2021-12-13 11:03:59,170: DEBUG - rocketchat-ynh-deps depends on mongodb-org-server; however: 2021-12-13 11:03:59,170: DEBUG - Package mongodb-org-server is not installed. 2021-12-13 11:03:59,170: DEBUG - rocketchat-ynh-deps depends on mongodb-org-tools; however: 2021-12-13 11:03:59,171: DEBUG - Package mongodb-org-tools is not installed. 2021-12-13 11:03:59,171: DEBUG - 2021-12-13 11:03:59,171: DEBUG - Setting up rocketchat-ynh-deps (4.2.1~ynh1) ... 2021-12-13 11:03:59,188: DEBUG - + ynh_package_install --fix-broken 2021-12-13 11:03:59,189: DEBUG - + ynh_apt --no-remove --option Dpkg::Options::=--force-confdef --option Dpkg::Options::=--force-confold install --fix-broken 2021-12-13 11:03:59,189: DEBUG - + ynh_wait_dpkg_free 2021-12-13 11:03:59,333: DEBUG - + return 0 2021-12-13 11:03:59,334: DEBUG - + LC_ALL=C 2021-12-13 11:03:59,334: DEBUG - + DEBIAN_FRONTEND=noninteractive 2021-12-13 11:03:59,334: DEBUG - + apt-get --assume-yes --quiet -o=Acquire::Retries=3 -o=Dpkg::Use-Pty=0 --no-remove --option Dpkg::Options::=--force-confdef --option Dpkg::Options::=--force-confold install --fix-broken 2021-12-13 11:03:59,711: DEBUG - Reading package lists... 2021-12-13 11:03:59,935: DEBUG - Building dependency tree... 2021-12-13 11:03:59,937: DEBUG - Reading state information... 2021-12-13 11:04:00,054: DEBUG - Correcting dependencies... Done 2021-12-13 11:04:00,263: DEBUG - The following additional packages will be installed: 2021-12-13 11:04:00,263: DEBUG - mongodb-database-tools mongodb-mongosh mongodb-org mongodb-org-database 2021-12-13 11:04:00,263: DEBUG - mongodb-org-database-tools-extra mongodb-org-mongos mongodb-org-server 2021-12-13 11:04:00,264: DEBUG - mongodb-org-shell mongodb-org-tools 2021-12-13 11:04:00,282: DEBUG - The following NEW packages will be installed: 2021-12-13 11:04:00,283: DEBUG - mongodb-database-tools mongodb-mongosh mongodb-org mongodb-org-database 2021-12-13 11:04:00,283: DEBUG - mongodb-org-database-tools-extra mongodb-org-mongos mongodb-org-server 2021-12-13 11:04:00,284: DEBUG - mongodb-org-shell mongodb-org-tools 2021-12-13 11:04:00,830: DEBUG - 0 upgraded, 9 newly installed, 0 to remove and 0 not upgraded. 2021-12-13 11:04:00,830: DEBUG - Need to get 0 B/145 MB of archives. 2021-12-13 11:04:00,831: DEBUG - After this operation, 457 MB of additional disk space will be used. 2021-12-13 11:04:00,859: DEBUG - Selecting previously unselected package mongodb-database-tools. 2021-12-13 11:04:00,908: DEBUG - (Reading database ... 64284 files and directories currently installed.) 2021-12-13 11:04:00,912: DEBUG - Preparing to unpack .../0-mongodb-database-tools_100.5.1_amd64.deb ... 2021-12-13 11:04:00,913: DEBUG - Unpacking mongodb-database-tools (100.5.1) ... 2021-12-13 11:04:05,304: DEBUG - Selecting previously unselected package mongodb-mongosh. 2021-12-13 11:04:05,315: DEBUG - Preparing to unpack .../1-mongodb-mongosh_1.1.6_amd64.deb ... 2021-12-13 11:04:05,319: DEBUG - Unpacking mongodb-mongosh (1.1.6) ... 2021-12-13 11:04:11,446: DEBUG - Selecting previously unselected package mongodb-org-shell. 2021-12-13 11:04:11,455: DEBUG - Preparing to unpack .../2-mongodb-org-shell_5.0.5_amd64.deb ... 2021-12-13 11:04:11,457: DEBUG - Unpacking mongodb-org-shell (5.0.5) ... 2021-12-13 11:04:13,581: DEBUG - Selecting previously unselected package mongodb-org-server. 2021-12-13 11:04:13,590: DEBUG - Preparing to unpack .../3-mongodb-org-server_5.0.5_amd64.deb ... 2021-12-13 11:04:13,592: DEBUG - Unpacking mongodb-org-server (5.0.5) ... 2021-12-13 11:04:17,275: DEBUG - Selecting previously unselected package mongodb-org-mongos. 2021-12-13 11:04:17,287: DEBUG - Preparing to unpack .../4-mongodb-org-mongos_5.0.5_amd64.deb ... 2021-12-13 11:04:17,290: DEBUG - Unpacking mongodb-org-mongos (5.0.5) ... 2021-12-13 11:04:19,972: DEBUG - Selecting previously unselected package mongodb-org-database-tools-extra. 2021-12-13 11:04:19,981: DEBUG - Preparing to unpack .../5-mongodb-org-database-tools-extra_5.0.5_amd64.deb ... 2021-12-13 11:04:19,982: DEBUG - Unpacking mongodb-org-database-tools-extra (5.0.5) ... 2021-12-13 11:04:20,002: DEBUG - Selecting previously unselected package mongodb-org-database. 2021-12-13 11:04:20,010: DEBUG - Preparing to unpack .../6-mongodb-org-database_5.0.5_amd64.deb ... 2021-12-13 11:04:20,015: DEBUG - Unpacking mongodb-org-database (5.0.5) ... 2021-12-13 11:04:20,034: DEBUG - Selecting previously unselected package mongodb-org-tools. 2021-12-13 11:04:20,043: DEBUG - Preparing to unpack .../7-mongodb-org-tools_5.0.5_amd64.deb ... 2021-12-13 11:04:20,045: DEBUG - Unpacking mongodb-org-tools (5.0.5) ... 2021-12-13 11:04:20,063: DEBUG - Selecting previously unselected package mongodb-org. 2021-12-13 11:04:20,071: DEBUG - Preparing to unpack .../8-mongodb-org_5.0.5_amd64.deb ... 2021-12-13 11:04:20,073: DEBUG - Unpacking mongodb-org (5.0.5) ... 2021-12-13 11:04:20,122: DEBUG - Setting up mongodb-mongosh (1.1.6) ... 2021-12-13 11:04:20,125: DEBUG - Setting up mongodb-org-server (5.0.5) ... 2021-12-13 11:04:20,486: DEBUG - Setting up mongodb-org-shell (5.0.5) ... 2021-12-13 11:04:20,489: DEBUG - Setting up mongodb-database-tools (100.5.1) ... 2021-12-13 11:04:20,494: DEBUG - Setting up mongodb-org-mongos (5.0.5) ... 2021-12-13 11:04:20,497: DEBUG - Setting up mongodb-org-database-tools-extra (5.0.5) ... 2021-12-13 11:04:20,500: DEBUG - Setting up mongodb-org-database (5.0.5) ... 2021-12-13 11:04:20,504: DEBUG - Setting up mongodb-org-tools (5.0.5) ... 2021-12-13 11:04:20,507: DEBUG - Setting up mongodb-org (5.0.5) ... 2021-12-13 11:04:20,512: DEBUG - Processing triggers for man-db (2.8.5-2) ... 2021-12-13 11:04:21,439: DEBUG - + [[ -n /tmp/tmp.LFAgu0mYVY ]] 2021-12-13 11:04:21,439: DEBUG - + rm --recursive --force /tmp/tmp.LFAgu0mYVY 2021-12-13 11:04:21,444: DEBUG - + ynh_package_is_installed rocketchat-ynh-deps 2021-12-13 11:04:21,458: DEBUG - + ynh_wait_dpkg_free 2021-12-13 11:04:21,617: DEBUG - + return 0 2021-12-13 11:04:21,618: DEBUG - + grep --count 'ok installed' 2021-12-13 11:04:21,618: DEBUG - + dpkg-query --show '--showformat=${Status}' rocketchat-ynh-deps 2021-12-13 11:04:21,640: DEBUG - + rm /tmp/rocketchat-ynh-deps.control 2021-12-13 11:04:21,642: DEBUG - + grep --quiet php 2021-12-13 11:04:21,645: DEBUG - + ynh_remove_extra_repo --name=rocketchat 2021-12-13 11:04:21,658: DEBUG - + name=rocketchat 2021-12-13 11:04:21,659: DEBUG - + ynh_secureremove --file=/etc/apt/sources.list.d/rocketchat.list 2021-12-13 11:04:21,691: DEBUG - + [[ rocketchat == \e\x\t\r\a_\p\h\p\\v\e\r\s\i\o\n ]] 2021-12-13 11:04:21,691: DEBUG - + ynh_secure_remove /etc/apt/preferences.d/rocketchat 2021-12-13 11:04:21,717: DEBUG - + ynh_secure_remove --file=/etc/apt/trusted.gpg.d/rocketchat.gpg 2021-12-13 11:04:21,740: DEBUG - + ynh_secure_remove --file=/etc/apt/trusted.gpg.d/rocketchat.asc 2021-12-13 11:04:21,763: DEBUG - + ynh_package_update 2021-12-13 11:04:21,764: DEBUG - + ynh_apt update 2021-12-13 11:04:21,764: DEBUG - + ynh_wait_dpkg_free 2021-12-13 11:04:21,764: INFO - '/etc/apt/trusted.gpg.d/rocketchat.asc' wasn't deleted because it doesn't exist. 2021-12-13 11:04:21,912: DEBUG - + return 0 2021-12-13 11:04:21,913: DEBUG - + LC_ALL=C 2021-12-13 11:04:21,913: DEBUG - + DEBIAN_FRONTEND=noninteractive 2021-12-13 11:04:21,913: DEBUG - + apt-get --assume-yes --quiet -o=Acquire::Retries=3 -o=Dpkg::Use-Pty=0 update 2021-12-13 11:04:22,149: DEBUG - Hit:1 http://forge.yunohost.org/debian buster InRelease 2021-12-13 11:04:22,183: DEBUG - Hit:2 http://deb.debian.org/debian buster InRelease 2021-12-13 11:04:22,193: DEBUG - Hit:3 http://security.debian.org/debian-security buster/updates InRelease 2021-12-13 11:04:22,549: DEBUG - Hit:4 https://collaboraoffice.com/repos/CollaboraOnline/CODE-debian10 ./ InRelease 2021-12-13 11:04:23,818: DEBUG - Reading package lists... 2021-12-13 11:04:23,878: DEBUG - + MONGODB_SERVICENAME=mongod 2021-12-13 11:04:23,878: DEBUG - + mongodb_servicename=mongod 2021-12-13 11:04:23,878: DEBUG - + systemctl is-enabled mongod -q 2021-12-13 11:04:23,925: DEBUG - + systemctl is-active mongod -q 2021-12-13 11:04:23,935: DEBUG - + ynh_systemd_action --service_name=mongod --action=restart '--line_match=aiting for connections' --log_path=/var/log/mongodb/mongod.log 2021-12-13 11:04:24,146: DEBUG - + service_name=mongod 2021-12-13 11:04:24,146: DEBUG - + action=restart 2021-12-13 11:04:24,146: DEBUG - + line_match='aiting for connections' 2021-12-13 11:04:24,146: DEBUG - + length=20 2021-12-13 11:04:24,146: DEBUG - + log_path=/var/log/mongodb/mongod.log 2021-12-13 11:04:24,147: DEBUG - + timeout=300 2021-12-13 11:04:24,147: DEBUG - + '[' restart == stop ']' 2021-12-13 11:04:24,147: DEBUG - + [[ -n aiting for connections ]] 2021-12-13 11:04:24,147: DEBUG - ++ mktemp 2021-12-13 11:04:24,150: DEBUG - + local templog=/tmp/tmp.PUEDApN5U7 2021-12-13 11:04:24,150: DEBUG - + '[' /var/log/mongodb/mongod.log == systemd ']' 2021-12-13 11:04:24,150: DEBUG - + local pid_tail=4993 2021-12-13 11:04:24,150: DEBUG - + '[' restart == reload ']' 2021-12-13 11:04:24,151: DEBUG - + systemctl restart mongod 2021-12-13 11:04:24,153: DEBUG - + tail --follow=name --retry --lines=0 /var/log/mongodb/mongod.log 2021-12-13 11:04:24,164: DEBUG - + [[ -n aiting for connections ]] 2021-12-13 11:04:53,271: WARNING - (this may take some time) 2021-12-13 11:09:25,154: DEBUG - + '[' 300 -ge 3 ']' 2021-12-13 11:09:25,155: DEBUG - + '[' 300 -eq 300 ']' 2021-12-13 11:09:25,155: DEBUG - + ynh_print_warn '--message=The service mongod didn'\''t fully executed the action restart before the timeout.' 2021-12-13 11:09:25,156: DEBUG - 2021-12-13 11:09:25,172: DEBUG - + ynh_print_log 'The service mongod didn'\''t fully executed the action restart before the timeout.' 2021-12-13 11:09:25,173: DEBUG - + echo -e 'The service mongod didn'\''t fully executed the action restart before the timeout.' 2021-12-13 11:09:25,173: WARNING - The service mongod didn't fully executed the action restart before the timeout. 2021-12-13 11:09:25,174: DEBUG - + ynh_print_warn '--message=Please find here an extract of the end of the log of the service mongod:' 2021-12-13 11:09:25,188: DEBUG - + ynh_print_log 'Please find here an extract of the end of the log of the service mongod:' 2021-12-13 11:09:25,188: DEBUG - + echo -e 'Please find here an extract of the end of the log of the service mongod:' 2021-12-13 11:09:25,188: DEBUG - + ynh_exec_warn journalctl --quiet --no-hostname --no-pager --lines=20 --unit=mongod 2021-12-13 11:09:25,188: DEBUG - + [[ 6 -eq 1 ]] 2021-12-13 11:09:25,189: WARNING - Please find here an extract of the end of the log of the service mongod: 2021-12-13 11:09:25,190: DEBUG - ++ journalctl --quiet --no-hostname --no-pager --lines=20 --unit=mongod 2021-12-13 11:09:25,203: DEBUG - + ynh_print_warn 'Dec 13 11:04:20 systemd[1]: /lib/systemd/system/mongod.service:11: PIDFile= references path below legacy directory /var/run/, updating /var/run/mongodb/mongod.pid → /run/mongodb/mongod.pid; please update the unit file accordingly. 2021-12-13 11:09:25,205: DEBUG - Dec 13 11:04:24 systemd[1]: Started MongoDB Database Server. 2021-12-13 11:09:25,205: DEBUG - Dec 13 11:04:24 systemd[1]: mongod.service: Main process exited, code=killed, status=4/ILL 2021-12-13 11:09:25,205: DEBUG - Dec 13 11:04:24 systemd[1]: mongod.service: Failed with result '\''signal'\''.' 2021-12-13 11:09:25,207: DEBUG - Dec 13 11:04:24 systemd[1]: Started MongoDB Database Server. 2021-12-13 11:09:25,207: DEBUG - Dec 13 11:04:24 systemd[1]: mongod.service: Main process exited, code=killed, status=4/ILL 2021-12-13 11:09:25,208: DEBUG - Dec 13 11:04:24 systemd[1]: mongod.service: Failed with result '\''signal'\''.' 2021-12-13 11:09:25,222: DEBUG - + ynh_print_log 'Dec 13 11:04:20 systemd[1]: /lib/systemd/system/mongod.service:11: PIDFile= references path below legacy directory /var/run/, updating /var/run/mongodb/mongod.pid → /run/mongodb/mongod.pid; please update the unit file accordingly. 2021-12-13 11:09:25,222: DEBUG - Dec 13 11:04:24 systemd[1]: Started MongoDB Database Server. 2021-12-13 11:09:25,223: DEBUG - Dec 13 11:04:24 systemd[1]: mongod.service: Main process exited, code=killed, status=4/ILL 2021-12-13 11:09:25,223: DEBUG - Dec 13 11:04:24 systemd[1]: mongod.service: Failed with result '\''signal'\''.' 2021-12-13 11:09:25,223: DEBUG - + echo -e 'Dec 13 11:04:20 systemd[1]: /lib/systemd/system/mongod.service:11: PIDFile= references path below legacy directory /var/run/, updating /var/run/mongodb/mongod.pid → /run/mongodb/mongod.pid; please update the unit file accordingly. 2021-12-13 11:09:25,223: DEBUG - Dec 13 11:04:24 systemd[1]: Started MongoDB Database Server. 2021-12-13 11:09:25,223: DEBUG - Dec 13 11:04:24 systemd[1]: mongod.service: Main process exited, code=killed, status=4/ILL 2021-12-13 11:09:25,223: DEBUG - Dec 13 11:04:24 systemd[1]: mongod.service: Failed with result '\''signal'\''.' 2021-12-13 11:09:25,223: DEBUG - + '[' -e /var/log/mongodb/mongod.log ']' 2021-12-13 11:09:25,223: DEBUG - + ynh_print_warn '--message=---' 2021-12-13 11:09:25,224: WARNING - Dec 13 11:04:20 systemd[1]: /lib/systemd/system/mongod.service:11: PIDFile= references path below legacy directory /var/run/, updating /var/run/mongodb/mongod.pid → /run/mongodb/mongod.pid; please update the unit file accordingly. 2021-12-13 11:09:25,225: WARNING - Dec 13 11:04:24 systemd[1]: Started MongoDB Database Server. 2021-12-13 11:09:25,226: WARNING - Dec 13 11:04:24 systemd[1]: mongod.service: Main process exited, code=killed, status=4/ILL 2021-12-13 11:09:25,226: WARNING - Dec 13 11:04:24 systemd[1]: mongod.service: Failed with result 'signal'. 2021-12-13 11:09:25,239: DEBUG - + ynh_print_log '---' 2021-12-13 11:09:25,239: DEBUG - + echo -e '---' 2021-12-13 11:09:25,239: DEBUG - + ynh_exec_warn tail --lines=20 /var/log/mongodb/mongod.log 2021-12-13 11:09:25,240: DEBUG - + [[ 3 -eq 1 ]] 2021-12-13 11:09:25,240: WARNING - --- 2021-12-13 11:09:25,241: DEBUG - ++ tail --lines=20 /var/log/mongodb/mongod.log 2021-12-13 11:09:25,246: DEBUG - + ynh_print_warn '{"t":{"$date":"2021-12-03T07:25:34.610-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"UnusedLockCleaner","durationMillis":17100}} 2021-12-13 11:09:25,246: DEBUG - {"t":{"$date":"2021-12-03T07:25:58.681-06:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"LogicalSessionCacheRefresh","msg":"Slow query","attr":{"type":"command","ns":"config.system.sessions","command":{"listIndexes":"system.sessions","cursor":{},"$db":"config"},"numYields":0,"reslen":245,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"protocol":"op_msg","durationMillis":296218}} 2021-12-13 11:09:25,246: DEBUG - {"t":{"$date":"2021-12-03T07:27:29.118-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1928}} 2021-12-13 11:09:25,246: DEBUG - {"t":{"$date":"2021-12-03T07:28:18.949-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1804}} 2021-12-13 11:09:25,246: DEBUG - {"t":{"$date":"2021-12-03T07:27:07.411-06:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"LogicalSessionCacheReap","msg":"Slow query","attr":{"type":"command","ns":"config.transactions","command":{"find":"transactions","filter":{"lastWriteDate":{"$lt":{"$date":"2021-12-03T12:51:53.803Z"}}},"projection":{"_id":1},"sort":{"_id":1},"readConcern":{},"$db":"config"},"planSummary":"EOF","keysExamined":0,"docsExamined":0,"cursorExhausted":true,"numYields":0,"nreturned":0,"reslen":108,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"readConcern":{"provenance":"clientSupplied"},"storage":{},"protocol":"op_msg","durationMillis":134679}} 2021-12-13 11:09:25,247: DEBUG - {"t":{"$date":"2021-12-03T07:29:13.431-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"UnusedLockCleaner","durationMillis":16920}} 2021-12-13 11:09:25,247: DEBUG - {"t":{"$date":"2021-12-03T07:30:56.333-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":2134}} 2021-12-13 11:09:25,247: DEBUG - {"t":{"$date":"2021-12-03T07:31:42.803-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":2279}} 2021-12-13 11:09:25,247: DEBUG - {"t":{"$date":"2021-12-03T07:32:33.976-06:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"WTCheckpointThread","msg":"WiredTiger message","attr":{"message":"[1638538340:108770][3461:0x7f7c86f1f700], WT_SESSION.checkpoint: [WT_VERB_CHECKPOINT_PROGRESS] saving checkpoint snapshot min: 9069, snapshot max: 9069 snapshot count: 0, oldest timestamp: (0, 0) , meta checkpoint timestamp: (0, 0) base write gen: 1"}} 2021-12-13 11:09:25,247: DEBUG - {"t":{"$date":"2021-12-03T07:32:47.281-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"UnusedLockCleaner","durationMillis":13376}} 2021-12-13 11:09:25,247: DEBUG - {"t":{"$date":"2021-12-03T07:34:41.372-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1899}} 2021-12-13 11:09:25,248: DEBUG - {"t":{"$date":"2021-12-03T07:35:27.373-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1129}} 2021-12-13 11:09:25,248: DEBUG - {"t":{"$date":"2021-12-03T07:36:17.623-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"UnusedLockCleaner","durationMillis":2558}} 2021-12-13 11:09:25,248: DEBUG - {"t":{"$date":"2021-12-03T07:37:55.380-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1667}} 2021-12-13 11:09:25,248: DEBUG - {"t":{"$date":"2021-12-03T07:36:49.458-06:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"LogicalSessionCacheRefresh","msg":"Slow query","attr":{"type":"command","ns":"config.system.sessions","command":{"listIndexes":"system.sessions","cursor":{},"$db":"config"},"numYields":0,"reslen":245,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"protocol":"op_msg","durationMillis":339939}} 2021-12-13 11:09:25,248: DEBUG - {"t":{"$date":"2021-12-03T07:38:40.321-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":2457}} 2021-12-13 11:09:25,248: DEBUG - {"t":{"$date":"2021-12-03T07:38:13.953-06:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"LogicalSessionCacheReap","msg":"Slow query","attr":{"type":"command","ns":"config.system.sessions","command":{"listIndexes":"system.sessions","cursor":{},"$db":"config"},"numYields":0,"reslen":245,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"protocol":"op_msg","durationMillis":294574}} 2021-12-13 11:09:25,248: DEBUG - {"t":{"$date":"2021-12-03T07:39:28.317-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"UnusedLockCleaner","durationMillis":6248}} 2021-12-13 11:09:25,249: DEBUG - {"t":{"$date":"2021-12-03T07:41:15.430-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1584}} 2021-12-13 11:09:25,250: DEBUG - {"t":{"$date":"2021-12-03T07:42:09.926-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1747}}' 2021-12-13 11:09:25,251: DEBUG - {"t":{"$date":"2021-12-03T07:25:58.681-06:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"LogicalSessionCacheRefresh","msg":"Slow query","attr":{"type":"command","ns":"config.system.sessions","command":{"listIndexes":"system.sessions","cursor":{},"$db":"config"},"numYields":0,"reslen":245,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"protocol":"op_msg","durationMillis":296218}} 2021-12-13 11:09:25,251: DEBUG - {"t":{"$date":"2021-12-03T07:27:29.118-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1928}} 2021-12-13 11:09:25,251: DEBUG - {"t":{"$date":"2021-12-03T07:28:18.949-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1804}} 2021-12-13 11:09:25,251: DEBUG - {"t":{"$date":"2021-12-03T07:27:07.411-06:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"LogicalSessionCacheReap","msg":"Slow query","attr":{"type":"command","ns":"config.transactions","command":{"find":"transactions","filter":{"lastWriteDate":{"$lt":{"$date":"2021-12-03T12:51:53.803Z"}}},"projection":{"_id":1},"sort":{"_id":1},"readConcern":{},"$db":"config"},"planSummary":"EOF","keysExamined":0,"docsExamined":0,"cursorExhausted":true,"numYields":0,"nreturned":0,"reslen":108,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"readConcern":{"provenance":"clientSupplied"},"storage":{},"protocol":"op_msg","durationMillis":134679}} 2021-12-13 11:09:25,252: DEBUG - {"t":{"$date":"2021-12-03T07:29:13.431-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"UnusedLockCleaner","durationMillis":16920}} 2021-12-13 11:09:25,252: DEBUG - {"t":{"$date":"2021-12-03T07:30:56.333-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":2134}} 2021-12-13 11:09:25,252: DEBUG - {"t":{"$date":"2021-12-03T07:31:42.803-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":2279}} 2021-12-13 11:09:25,252: DEBUG - {"t":{"$date":"2021-12-03T07:32:33.976-06:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"WTCheckpointThread","msg":"WiredTiger message","attr":{"message":"[1638538340:108770][3461:0x7f7c86f1f700], WT_SESSION.checkpoint: [WT_VERB_CHECKPOINT_PROGRESS] saving checkpoint snapshot min: 9069, snapshot max: 9069 snapshot count: 0, oldest timestamp: (0, 0) , meta checkpoint timestamp: (0, 0) base write gen: 1"}} 2021-12-13 11:09:25,252: DEBUG - {"t":{"$date":"2021-12-03T07:32:47.281-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"UnusedLockCleaner","durationMillis":13376}} 2021-12-13 11:09:25,253: DEBUG - {"t":{"$date":"2021-12-03T07:34:41.372-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1899}} 2021-12-13 11:09:25,254: DEBUG - {"t":{"$date":"2021-12-03T07:35:27.373-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1129}} 2021-12-13 11:09:25,254: DEBUG - {"t":{"$date":"2021-12-03T07:36:17.623-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"UnusedLockCleaner","durationMillis":2558}} 2021-12-13 11:09:25,254: DEBUG - {"t":{"$date":"2021-12-03T07:37:55.380-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1667}} 2021-12-13 11:09:25,254: DEBUG - {"t":{"$date":"2021-12-03T07:36:49.458-06:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"LogicalSessionCacheRefresh","msg":"Slow query","attr":{"type":"command","ns":"config.system.sessions","command":{"listIndexes":"system.sessions","cursor":{},"$db":"config"},"numYields":0,"reslen":245,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"protocol":"op_msg","durationMillis":339939}} 2021-12-13 11:09:25,254: DEBUG - {"t":{"$date":"2021-12-03T07:38:40.321-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":2457}} 2021-12-13 11:09:25,255: DEBUG - {"t":{"$date":"2021-12-03T07:38:13.953-06:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"LogicalSessionCacheReap","msg":"Slow query","attr":{"type":"command","ns":"config.system.sessions","command":{"listIndexes":"system.sessions","cursor":{},"$db":"config"},"numYields":0,"reslen":245,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"protocol":"op_msg","durationMillis":294574}} 2021-12-13 11:09:25,255: DEBUG - {"t":{"$date":"2021-12-03T07:39:28.317-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"UnusedLockCleaner","durationMillis":6248}} 2021-12-13 11:09:25,255: DEBUG - {"t":{"$date":"2021-12-03T07:41:15.430-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1584}} 2021-12-13 11:09:25,255: DEBUG - {"t":{"$date":"2021-12-03T07:42:09.926-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1747}}' 2021-12-13 11:09:25,269: DEBUG - + ynh_print_log '{"t":{"$date":"2021-12-03T07:25:34.610-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"UnusedLockCleaner","durationMillis":17100}} 2021-12-13 11:09:25,269: DEBUG - {"t":{"$date":"2021-12-03T07:25:58.681-06:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"LogicalSessionCacheRefresh","msg":"Slow query","attr":{"type":"command","ns":"config.system.sessions","command":{"listIndexes":"system.sessions","cursor":{},"$db":"config"},"numYields":0,"reslen":245,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"protocol":"op_msg","durationMillis":296218}} 2021-12-13 11:09:25,270: DEBUG - {"t":{"$date":"2021-12-03T07:27:29.118-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1928}} 2021-12-13 11:09:25,270: DEBUG - {"t":{"$date":"2021-12-03T07:28:18.949-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1804}} 2021-12-13 11:09:25,270: DEBUG - {"t":{"$date":"2021-12-03T07:27:07.411-06:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"LogicalSessionCacheReap","msg":"Slow query","attr":{"type":"command","ns":"config.transactions","command":{"find":"transactions","filter":{"lastWriteDate":{"$lt":{"$date":"2021-12-03T12:51:53.803Z"}}},"projection":{"_id":1},"sort":{"_id":1},"readConcern":{},"$db":"config"},"planSummary":"EOF","keysExamined":0,"docsExamined":0,"cursorExhausted":true,"numYields":0,"nreturned":0,"reslen":108,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"readConcern":{"provenance":"clientSupplied"},"storage":{},"protocol":"op_msg","durationMillis":134679}} 2021-12-13 11:09:25,270: DEBUG - {"t":{"$date":"2021-12-03T07:29:13.431-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"UnusedLockCleaner","durationMillis":16920}} 2021-12-13 11:09:25,270: DEBUG - {"t":{"$date":"2021-12-03T07:30:56.333-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":2134}} 2021-12-13 11:09:25,270: DEBUG - {"t":{"$date":"2021-12-03T07:31:42.803-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":2279}} 2021-12-13 11:09:25,271: DEBUG - {"t":{"$date":"2021-12-03T07:32:33.976-06:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"WTCheckpointThread","msg":"WiredTiger message","attr":{"message":"[1638538340:108770][3461:0x7f7c86f1f700], WT_SESSION.checkpoint: [WT_VERB_CHECKPOINT_PROGRESS] saving checkpoint snapshot min: 9069, snapshot max: 9069 snapshot count: 0, oldest timestamp: (0, 0) , meta checkpoint timestamp: (0, 0) base write gen: 1"}} 2021-12-13 11:09:25,271: DEBUG - {"t":{"$date":"2021-12-03T07:32:47.281-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"UnusedLockCleaner","durationMillis":13376}} 2021-12-13 11:09:25,271: DEBUG - {"t":{"$date":"2021-12-03T07:34:41.372-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1899}} 2021-12-13 11:09:25,271: DEBUG - {"t":{"$date":"2021-12-03T07:35:27.373-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1129}} 2021-12-13 11:09:25,271: DEBUG - {"t":{"$date":"2021-12-03T07:36:17.623-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"UnusedLockCleaner","durationMillis":2558}} 2021-12-13 11:09:25,271: DEBUG - {"t":{"$date":"2021-12-03T07:37:55.380-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1667}} 2021-12-13 11:09:25,272: DEBUG - {"t":{"$date":"2021-12-03T07:36:49.458-06:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"LogicalSessionCacheRefresh","msg":"Slow query","attr":{"type":"command","ns":"config.system.sessions","command":{"listIndexes":"system.sessions","cursor":{},"$db":"config"},"numYields":0,"reslen":245,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"protocol":"op_msg","durationMillis":339939}} 2021-12-13 11:09:25,272: DEBUG - {"t":{"$date":"2021-12-03T07:38:40.321-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":2457}} 2021-12-13 11:09:25,272: DEBUG - {"t":{"$date":"2021-12-03T07:38:13.953-06:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"LogicalSessionCacheReap","msg":"Slow query","attr":{"type":"command","ns":"config.system.sessions","command":{"listIndexes":"system.sessions","cursor":{},"$db":"config"},"numYields":0,"reslen":245,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"protocol":"op_msg","durationMillis":294574}} 2021-12-13 11:09:25,272: DEBUG - {"t":{"$date":"2021-12-03T07:39:28.317-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"UnusedLockCleaner","durationMillis":6248}} 2021-12-13 11:09:25,272: DEBUG - {"t":{"$date":"2021-12-03T07:41:15.430-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1584}} 2021-12-13 11:09:25,272: DEBUG - {"t":{"$date":"2021-12-03T07:42:09.926-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1747}}' 2021-12-13 11:09:25,272: DEBUG - + echo -e '{"t":{"$date":"2021-12-03T07:25:34.610-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"UnusedLockCleaner","durationMillis":17100}} 2021-12-13 11:09:25,273: DEBUG - {"t":{"$date":"2021-12-03T07:25:58.681-06:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"LogicalSessionCacheRefresh","msg":"Slow query","attr":{"type":"command","ns":"config.system.sessions","command":{"listIndexes":"system.sessions","cursor":{},"$db":"config"},"numYields":0,"reslen":245,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"protocol":"op_msg","durationMillis":296218}} 2021-12-13 11:09:25,273: DEBUG - {"t":{"$date":"2021-12-03T07:27:29.118-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1928}} 2021-12-13 11:09:25,274: DEBUG - {"t":{"$date":"2021-12-03T07:28:18.949-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1804}} 2021-12-13 11:09:25,274: DEBUG - {"t":{"$date":"2021-12-03T07:27:07.411-06:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"LogicalSessionCacheReap","msg":"Slow query","attr":{"type":"command","ns":"config.transactions","command":{"find":"transactions","filter":{"lastWriteDate":{"$lt":{"$date":"2021-12-03T12:51:53.803Z"}}},"projection":{"_id":1},"sort":{"_id":1},"readConcern":{},"$db":"config"},"planSummary":"EOF","keysExamined":0,"docsExamined":0,"cursorExhausted":true,"numYields":0,"nreturned":0,"reslen":108,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"readConcern":{"provenance":"clientSupplied"},"storage":{},"protocol":"op_msg","durationMillis":134679}} 2021-12-13 11:09:25,274: DEBUG - {"t":{"$date":"2021-12-03T07:29:13.431-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"UnusedLockCleaner","durationMillis":16920}} 2021-12-13 11:09:25,274: DEBUG - {"t":{"$date":"2021-12-03T07:30:56.333-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":2134}} 2021-12-13 11:09:25,274: DEBUG - {"t":{"$date":"2021-12-03T07:31:42.803-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":2279}} 2021-12-13 11:09:25,274: DEBUG - {"t":{"$date":"2021-12-03T07:32:33.976-06:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"WTCheckpointThread","msg":"WiredTiger message","attr":{"message":"[1638538340:108770][3461:0x7f7c86f1f700], WT_SESSION.checkpoint: [WT_VERB_CHECKPOINT_PROGRESS] saving checkpoint snapshot min: 9069, snapshot max: 9069 snapshot count: 0, oldest timestamp: (0, 0) , meta checkpoint timestamp: (0, 0) base write gen: 1"}} 2021-12-13 11:09:25,274: DEBUG - {"t":{"$date":"2021-12-03T07:32:47.281-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"UnusedLockCleaner","durationMillis":13376}} 2021-12-13 11:09:25,275: DEBUG - {"t":{"$date":"2021-12-03T07:34:41.372-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1899}} 2021-12-13 11:09:25,275: DEBUG - {"t":{"$date":"2021-12-03T07:35:27.373-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1129}} 2021-12-13 11:09:25,275: DEBUG - {"t":{"$date":"2021-12-03T07:36:17.623-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"UnusedLockCleaner","durationMillis":2558}} 2021-12-13 11:09:25,275: DEBUG - {"t":{"$date":"2021-12-03T07:37:55.380-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1667}} 2021-12-13 11:09:25,275: DEBUG - {"t":{"$date":"2021-12-03T07:36:49.458-06:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"LogicalSessionCacheRefresh","msg":"Slow query","attr":{"type":"command","ns":"config.system.sessions","command":{"listIndexes":"system.sessions","cursor":{},"$db":"config"},"numYields":0,"reslen":245,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"protocol":"op_msg","durationMillis":339939}} 2021-12-13 11:09:25,275: DEBUG - {"t":{"$date":"2021-12-03T07:38:40.321-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":2457}} 2021-12-13 11:09:25,275: DEBUG - {"t":{"$date":"2021-12-03T07:38:13.953-06:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"LogicalSessionCacheReap","msg":"Slow query","attr":{"type":"command","ns":"config.system.sessions","command":{"listIndexes":"system.sessions","cursor":{},"$db":"config"},"numYields":0,"reslen":245,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"protocol":"op_msg","durationMillis":294574}} 2021-12-13 11:09:25,276: DEBUG - {"t":{"$date":"2021-12-03T07:39:28.317-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"UnusedLockCleaner","durationMillis":6248}} 2021-12-13 11:09:25,276: DEBUG - {"t":{"$date":"2021-12-03T07:41:15.430-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1584}} 2021-12-13 11:09:25,276: DEBUG - {"t":{"$date":"2021-12-03T07:42:09.926-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1747}}' 2021-12-13 11:09:25,276: DEBUG - + ynh_clean_check_starting 2021-12-13 11:09:25,276: DEBUG - + '[' -n 4993 ']' 2021-12-13 11:09:25,276: DEBUG - + kill -SIGTERM 4993 2021-12-13 11:09:25,276: WARNING - {"t":{"$date":"2021-12-03T07:25:34.610-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"UnusedLockCleaner","durationMillis":17100}} 2021-12-13 11:09:25,279: WARNING - {"t":{"$date":"2021-12-03T07:25:58.681-06:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"LogicalSessionCacheRefresh","msg":"Slow query","attr":{"type":"command","ns":"config.system.sessions","command":{"listIndexes":"system.sessions","cursor":{},"$db":"config"},"numYields":0,"reslen":245,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"protocol":"op_msg","durationMillis":296218}} 2021-12-13 11:09:25,280: WARNING - {"t":{"$date":"2021-12-03T07:27:29.118-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1928}} 2021-12-13 11:09:25,280: WARNING - {"t":{"$date":"2021-12-03T07:28:18.949-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1804}} 2021-12-13 11:09:25,281: WARNING - {"t":{"$date":"2021-12-03T07:27:07.411-06:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"LogicalSessionCacheReap","msg":"Slow query","attr":{"type":"command","ns":"config.transactions","command":{"find":"transactions","filter":{"lastWriteDate":{"$lt":{"$date":"2021-12-03T12:51:53.803Z"}}},"projection":{"_id":1},"sort":{"_id":1},"readConcern":{},"$db":"config"},"planSummary":"EOF","keysExamined":0,"docsExamined":0,"cursorExhausted":true,"numYields":0,"nreturned":0,"reslen":108,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"readConcern":{"provenance":"clientSupplied"},"storage":{},"protocol":"op_msg","durationMillis":134679}} 2021-12-13 11:09:25,283: WARNING - {"t":{"$date":"2021-12-03T07:29:13.431-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"UnusedLockCleaner","durationMillis":16920}} 2021-12-13 11:09:25,284: WARNING - {"t":{"$date":"2021-12-03T07:30:56.333-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":2134}} 2021-12-13 11:09:25,285: WARNING - {"t":{"$date":"2021-12-03T07:31:42.803-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":2279}} 2021-12-13 11:09:25,288: WARNING - {"t":{"$date":"2021-12-03T07:32:33.976-06:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"WTCheckpointThread","msg":"WiredTiger message","attr":{"message":"[1638538340:108770][3461:0x7f7c86f1f700], WT_SESSION.checkpoint: [WT_VERB_CHECKPOINT_PROGRESS] saving checkpoint snapshot min: 9069, snapshot max: 9069 snapshot count: 0, oldest timestamp: (0, 0) , meta checkpoint timestamp: (0, 0) base write gen: 1"}} 2021-12-13 11:09:25,289: WARNING - {"t":{"$date":"2021-12-03T07:32:47.281-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"UnusedLockCleaner","durationMillis":13376}} 2021-12-13 11:09:25,295: WARNING - {"t":{"$date":"2021-12-03T07:34:41.372-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1899}} 2021-12-13 11:09:25,295: WARNING - {"t":{"$date":"2021-12-03T07:35:27.373-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1129}} 2021-12-13 11:09:25,296: WARNING - {"t":{"$date":"2021-12-03T07:36:17.623-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"UnusedLockCleaner","durationMillis":2558}} 2021-12-13 11:09:25,296: WARNING - {"t":{"$date":"2021-12-03T07:37:55.380-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1667}} 2021-12-13 11:09:25,297: WARNING - {"t":{"$date":"2021-12-03T07:36:49.458-06:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"LogicalSessionCacheRefresh","msg":"Slow query","attr":{"type":"command","ns":"config.system.sessions","command":{"listIndexes":"system.sessions","cursor":{},"$db":"config"},"numYields":0,"reslen":245,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"protocol":"op_msg","durationMillis":339939}} 2021-12-13 11:09:25,297: WARNING - {"t":{"$date":"2021-12-03T07:38:40.321-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":2457}} 2021-12-13 11:09:25,298: WARNING - {"t":{"$date":"2021-12-03T07:38:13.953-06:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"LogicalSessionCacheReap","msg":"Slow query","attr":{"type":"command","ns":"config.system.sessions","command":{"listIndexes":"system.sessions","cursor":{},"$db":"config"},"numYields":0,"reslen":245,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"protocol":"op_msg","durationMillis":294574}} 2021-12-13 11:09:25,298: WARNING - {"t":{"$date":"2021-12-03T07:39:28.317-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"UnusedLockCleaner","durationMillis":6248}} 2021-12-13 11:09:25,299: WARNING - {"t":{"$date":"2021-12-03T07:41:15.430-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1584}} 2021-12-13 11:09:25,299: WARNING - {"t":{"$date":"2021-12-03T07:42:09.926-06:00"},"s":"I", "c":"COMMAND", "id":23099, "ctx":"PeriodicTaskRunner","msg":"Task finished","attr":{"taskName":"DBConnectionPool-cleaner","durationMillis":1747}} 2021-12-13 11:09:25,300: DEBUG - + '[' -n /tmp/tmp.PUEDApN5U7 ']' 2021-12-13 11:09:25,300: DEBUG - + ynh_secure_remove --file=/tmp/tmp.PUEDApN5U7 2021-12-13 11:09:25,316: DEBUG - + yunohost service add mongod '--description=MongoDB daemon' --log=/var/log/mongodb/mongod.log 2021-12-13 11:09:25,755: DEBUG - The service 'mongod' was added 2021-12-13 11:09:25,853: INFO - [#########...........] > Creating a MongoDB database... 2021-12-13 11:09:25,855: DEBUG - ++ ynh_sanitize_dbid --db_name=rocketchat 2021-12-13 11:09:25,872: DEBUG - ++ echo rocketchat 2021-12-13 11:09:25,873: DEBUG - + db_name=rocketchat 2021-12-13 11:09:25,873: DEBUG - + db_user=rocketchat 2021-12-13 11:09:25,873: DEBUG - + ynh_app_setting_set --app=rocketchat --key=db_name --value=rocketchat 2021-12-13 11:09:25,873: DEBUG - + local _globalapp=rocketchat 2021-12-13 11:09:25,971: DEBUG - + app=rocketchat 2021-12-13 11:09:25,972: DEBUG - + [[ dbname =~ (unprotected|protected|skipped) ]] 2021-12-13 11:09:25,972: DEBUG - + ynh_app_setting set rocketchat db_name rocketchat 2021-12-13 11:09:26,028: DEBUG - + ynh_mongo_setup_db --db_user=rocketchat --db_name=rocketchat 2021-12-13 11:09:26,029: DEBUG - + db_pwd= 2021-12-13 11:09:26,084: DEBUG - ++ ynh_string_random 2021-12-13 11:09:26,086: DEBUG - ++ length=24 2021-12-13 11:09:26,087: DEBUG - ++ sed --quiet 's/(.{24}).*/\1/p' 2021-12-13 11:09:26,089: DEBUG - ++ tr --complement --delete A-Za-z0-9 2021-12-13 11:09:26,090: DEBUG - ++ dd if=/dev/urandom bs=1 count=1000 2021-12-13 11:09:26,099: DEBUG - + local new_db_pwd=** 2021-12-13 11:09:26,099: DEBUG - + db_pwd=** 2021-12-13 11:09:26,099: DEBUG - + ynh_mongo_create_user --db_user=rocketchat --db_pwd=** --db_name=rocketchat 2021-12-13 11:09:26,185: DEBUG - + ynh_mongo_exec --database=rocketchat '--command=db.createUser( { user: "rocketchat", pwd: "**", roles: [ { role: "readWrite", db: "rocketchat" } ] } );' 2021-12-13 11:09:26,318: DEBUG - + user= 2021-12-13 11:09:26,318: DEBUG - + password= 2021-12-13 11:09:26,318: DEBUG - + authenticationdatabase= 2021-12-13 11:09:26,319: DEBUG - + database=rocketchat 2021-12-13 11:09:26,319: DEBUG - + host= 2021-12-13 11:09:26,319: DEBUG - + port= 2021-12-13 11:09:26,319: DEBUG - + eval=0 2021-12-13 11:09:26,319: DEBUG - + '[' -n '' ']' 2021-12-13 11:09:26,319: DEBUG - + password= 2021-12-13 11:09:26,319: DEBUG - + authenticationdatabase= 2021-12-13 11:09:26,319: DEBUG - + '[' -n '' ']' 2021-12-13 11:09:26,319: DEBUG - + '[' -n '' ']' 2021-12-13 11:09:26,320: DEBUG - + '[' -n rocketchat ']' 2021-12-13 11:09:26,320: DEBUG - + database='use rocketchat' 2021-12-13 11:09:26,320: DEBUG - + mongo --quiet 2021-12-13 11:09:26,369: WARNING - _common.sh: line 45: 6063 Illegal instruction mongo --quiet $user $password $authenticationdatabase $host $port <<EOF 2021-12-13 11:09:26,369: WARNING - $database 2021-12-13 11:09:26,370: WARNING - ${command} 2021-12-13 11:09:26,370: WARNING - quit() 2021-12-13 11:09:26,372: WARNING - EOF 2021-12-13 11:09:26,372: DEBUG - 2021-12-13 11:09:26,373: DEBUG - + ynh_exit_properly 2021-12-13 11:09:26,373: DEBUG - + local exit_code=132 2021-12-13 11:09:26,376: DEBUG - + '[' 132 -eq 0 ']' 2021-12-13 11:09:26,879: DEBUG - + ynh_clean_setup 2021-12-13 11:09:26,879: DEBUG - + true 2021-12-13 11:09:27,880: ERROR - Unable to install rocketchat: An error occurred inside the app installation script

YunoHost-Apps / rocketchat_ynh