Synapse backup/restore failed

My YunoHost server

Hardware: Raspberry Pi for backup create / AMD64 for backup restore
YunoHost version: 3.6.4.6 (stable)
I have access to my server : Through SSH
Are you in a special context or did you perform some particular tweaking on your YunoHost instance ? : no

Description of my issue

Hi everyone,

I have an yunohost on a raspberry pi working fine, and I want to upgrade my hardware on a amd64 board.

The main issue is with the synapse backup / restore. The backup work with the command :
sudo yunohost backup create --apps synapse --debug

20551 INFO Now creating a backup archive from the files collected…
20552 DEBUG Creating the backup tar archive…
331786 DEBUG Backup tar archive created
331794 SUCCESS Backup created
331795 DEBUG action [22561.1] executed in 330.154s
331796 DEBUG lock has been released
name: 20191007-200134
results: 
  apps: 
    synapse: Success
  system: 
size: 1330918692

But there are some warnings, for example :

11574 DEBUG + local dest=apps/synapse/backup/data
11575 DEBUG + echo '"/var/lib/matrix-synapse","apps/synapse/backup/data"'
11575 DEBUG ++ dirname /home/yunohost.backup/tmp/20191007-200134/apps/synapse/backup/data
11576 DEBUG + mkdir -p /home/yunohost.backup/tmp/20191007-200134/apps/synapse/backup
11577 DEBUG + ynh_psql_dump_db matrix_synapse
11578 DEBUG + db=matrix_synapse
11579 DEBUG + su '--command=pg_dump "matrix_synapse"' postgres
15091 WARNING could not change directory to "/home/yunohost.backup/tmp/20191007-200134/apps/synapse/backup": Permission denied

Then, when I restore the backup like this :
sudo yunohost backup restore 20191007-200134 --debug
And I got some warnings :

365865 DEBUG + ynh_psql_remove_db matrix_synapse matrix_synapse
365867 DEBUG + db=matrix_synapse
365870 DEBUG + user=matrix_synapse
365872 DEBUG + su '--command=dropdb "matrix_synapse"' postgres
366277 WARNING could not change directory to "/home/yunohost.backup/tmp/20191007-200134/apps/synapse/settings/scripts": Permission denied
366582 DEBUG + ynh_psql_drop_user matrix_synapse
366587 DEBUG + user=matrix_synapse
366595 DEBUG + su '--command=dropuser "matrix_synapse"' postgres
366999 DEBUG + ynh_system_user_delete matrix-synapse
367000 WARNING could not change directory to "/home/yunohost.backup/tmp/20191007-200134/apps/synapse/settings/scripts": Permission denied

Finaley, I can share the following log : sudo yunohost log display 20191007-203407-backup_restore_app-synapse

description: Restore 'synapse' from a backup archive
log_path: /var/log/yunohost/categories/operation/20191007-203407-backup_restore_app-synapse.log
logs: 
  - ct of the log before the crash:
  - 2019-10-07 22:36:31,228: DEBUG - + local message
  - 2019-10-07 22:36:31,229: WARNING - [DEBUG]: DEBUG      moulinette.actionsmap process - action [20357.1] executed in 0.075s
  - 2019-10-07 22:36:31,231: DEBUG - + ynh_handle_getopts_args '--message=!!\n  synapse'\''s script has encountered an error. Its execution was cancelled.\n!!'
  - 2019-10-07 22:36:31,233: WARNING - [DEBUG]: DEBUG   - The service 'matrix-synapse' has been added
  - 2019-10-07 22:36:31,234: DEBUG - + set +x
  - 2019-10-07 22:36:31,235: WARNING - [DEBUG]: DEBUG   - + yunohost service add coturn-synapse
  - 2019-10-07 22:36:31,236: DEBUG - + ynh_print_log '\e[91m\e[1m[ERR]\e[0m !!\n synapse'\''s script has encountered an error. Its execution was cancelled.\n!!'
  - 2019-10-07 22:36:31,237: WARNING - [DEBUG]: DEBUG      moulinette.actionsmap __init__ - loading actions map namespace 'yunohost'
  - 2019-10-07 22:36:31,239: DEBUG - + echo -e '\e[91m\e[1m[ERR]\e[0m !!\n synapse'\''s script has encountered an error. Its execution was cancelled.\n!!'
  - 2019-10-07 22:36:31,240: WARNING - [DEBUG]: DEBUG      moulinette.actionsmap __init__ - extra parameter classes loaded: ['comment', 'ask', 'password', 'required', 'pattern']
  - 2019-10-07 22:36:31,241: DEBUG - + '[' cli == cli ']'
  - 2019-10-07 22:36:31,242: WARNING - [DEBUG]: DEBUG      moulinette.interface __init__ - initializing base actions map parser for cli
  - 2019-10-07 22:36:31,243: DEBUG - + set +x
  - 2019-10-07 22:36:31,244: WARNING - [DEBUG]: DEBUG      moulinette.interface __init__ - registering new callback action 'yunohost.utils.packages.ynh_packages_**********' to ['-v', '--**********']
  - 2019-10-07 22:36:31,245: DEBUG - + type -t ynh_clean_setup
  - 2019-10-07 22:36:31,247: WARNING - [DEBUG]: DEBUG      moulinette.actionsmap process - loading python module yunohost.service took 0.004s
  - 2019-10-07 22:36:31,248: DEBUG - + ynh_die
  - 2019-10-07 22:36:31,249: WARNING - [DEBUG]: INFO        moulinette.actionsmap process - processing action [20358.1]: yunohost.service.add with args={'status': None, 'description': None, 'need_lock': False, 'log': None, 'runlevel': None, 'log_type': 'file', 'name': 'coturn-synapse'}
  - 2019-10-07 22:36:31,251: DEBUG - + local legacy_args=mc
  - 2019-10-07 22:36:31,252: WARNING - [DEBUG]: SUCCESS  yunohost.service success - [20358.1] The service 'coturn-synapse' has been added
  - 2019-10-07 22:36:31,253: DEBUG - + args_array=([m]=message= [c]=ret_code=)
  - 2019-10-07 22:36:31,254: WARNING - [DEBUG]: DEBUG      moulinette.actionsmap process - action [20358.1] executed in 0.080s
  - 2019-10-07 22:36:31,256: DEBUG - + declare -Ar args_array
  - 2019-10-07 22:36:31,257: WARNING - [DEBUG]: DEBUG   - The service 'coturn-synapse' has been added
  - 2019-10-07 22:36:31,258: DEBUG - + local message
  - 2019-10-07 22:36:31,259: WARNING - [DEBUG]: DEBUG   - + systemctl reload nginx.service
  - 2019-10-07 22:36:31,260: DEBUG - + local ret_code
  - 2019-10-07 22:36:31,262: WARNING - [DEBUG]: DEBUG   - + systemctl restart coturn-synapse.service
  - 2019-10-07 22:36:31,263: DEBUG - + ynh_handle_getopts_args
  - 2019-10-07 22:36:31,264: WARNING - [DEBUG]: DEBUG   - + ynh_check_starting 'Synapse now listening on TCP port 8448' /var/log/matrix-synapse/homeserver.log 300 matrix-synapse
  - 2019-10-07 22:36:31,265: DEBUG - + set +x
  - 2019-10-07 22:36:31,267: WARNING - [DEBUG]: WARNING - Starting of matrix-synapse
  - 2019-10-07 22:36:31,268: DEBUG - + echo ''
  - 2019-10-07 22:36:31,269: WARNING - [DEBUG]: DEBUG   - + local 'line_to_match=Synapse now listening on TCP port 8448'
  - 2019-10-07 22:36:31,270: DEBUG - + exit 1
  - 2019-10-07 22:36:31,272: WARNING - [DEBUG]: DEBUG   - + local service_name=matrix-synapse
  - 2019-10-07 22:36:31,273: WARNING - [DEBUG]: DEBUG   - + local app_log=/var/log/matrix-synapse/homeserver.log
  - 2019-10-07 22:36:31,274: WARNING - [DEBUG]: DEBUG   - + local timeout=300
  - 2019-10-07 22:36:31,276: WARNING - [DEBUG]: DEBUG   - + echo 'Starting of matrix-synapse'
  - 2019-10-07 22:36:31,277: WARNING - [DEBUG]: DEBUG   - + systemctl restart matrix-synapse
  - 2019-10-07 22:36:31,278: WARNING - [DEBUG]: DEBUG   - + ynh_exit_properly
  - 2019-10-07 22:36:31,279: WARNING - 
  - 2019-10-07 22:36:31,412: ERROR - Unable to restore the app 'synapse'
  - Traceback (most recent call last):
  -   File "/usr/lib/moulinette/yunohost/backup.py", line 1325, in _restore_app
  -     env=env_dict)[0]
  -   File "/usr/lib/moulinette/yunohost/hook.py", line 397, in hook_exec
  -     raise YunohostError('hook_exec_failed', path=path)
  - YunohostError: Script execution failed: /tmp/restorexd7FKL/restore
metadata: 
  ended_at: 2019-10-07 22:36:31
  env: 
    YNH_APP_BACKUP_DIR: /home/yunohost.backup/tmp/20191007-200134/apps/synapse/backup
    YNH_APP_ID: synapse
    YNH_APP_INSTANCE_NAME: synapse
    YNH_APP_INSTANCE_NUMBER: 1
    YNH_BACKUP_CSV: /home/yunohost.backup/tmp/20191007-200134/backup.csv
    YNH_BACKUP_DIR: /home/yunohost.backup/tmp/20191007-200134
    YNH_CWD: /home/yunohost.backup/tmp/20191007-200134/apps/synapse/backup
    YNH_INTERFACE: cli
    YNH_STDINFO: /tmp/tmpbpQ1cA/stdinfo
    YNH_STDRETURN: /tmp/tmpb1ZmJz/stdreturn
  error: Unable to restore the app 'synapse'
  operation: backup_restore_app
  related_to: 
    - app
    - synapse
  started_at: 2019-10-07 22:34:07
  success: False
metadata_path: /var/log/yunohost/categories/operation/20191007-203407-backup_restore_app-synapse.yml
name: 20191007-203407-backup_restore_app-synapse

Does anyone had an idea how to solve this ?

Cheers,
Ludovic

Hi,

I tried to investigate, but it is hard to progress for me :disappointed:

So far, I understood that the restore failed here :

systemctl reload nginx.service
systemctl restart coturn-$app.service
ynh_check_starting “Synapse now listening on TCP port $synapse_tls_port” “/var/log/matrix-$app/homeserver.log” 300 “matrix-$app”

Unfortunately (but I could imaging why), the script remove everything after a failed, so I don’t know where to looked.
I try to execute the script step by step, but now I don’t know how to prepare the archive for restoration. I looked for it in the yunohost github (backup.py), but it is not easy to read/understand the steps for how to prepare the archive.

Does someones has any clue how I can prepare the archive in order to execute restore script step by step ?

Ludovic

Uuuuh I think running the restore step by step is gonna be complicated … but what I can see is that it fails when trying to start matrix as you found out :

+ ynh_check_starting 'Synapse now listening on TCP port 8448' /var/log/matrix-synapse/homeserver.log 300 matrix-synapse
+ local 'line_to_match=Synapse now listening on TCP port 8448'
+ local service_name=matrix-synapse
+ local app_log=/var/log/matrix-synapse/homeserver.log
+ local timeout=300
+ echo 'Starting of matrix-synapse'
+ systemctl restart matrix-synapse
+ ynh_exit_properly

so right after the systemctl restart

Knowing that, I guess you should investigate the logfiles of Matrix / Synapse : supposedly /var/log/matrix-synapse/homeserver.log - or maybe /var/log/daemon.log to look for the actual error message the daemon encountered ?

Thank you @Aleks for your reply !

So, nothing in /var/log/matrix-synapse/homeserver.log because the failed backup script removed it :disappointed:

But they are some stuff on /var/log/daemon.log:

Oct 14 21:59:01 mydomain nslcd[891]: [bfe8e0] <passwd=“ynh*”> request denied by validnames option
Oct 14 22:00:11 mydomain systemd[1]: Reloading.
Oct 14 22:00:29 mydomain systemd[1]: Reloading.
Oct 14 22:00:29 mydomain systemd[1]: Reloading.
Oct 14 22:00:29 mydomain systemd[1]: Starting LSB: coturn TURN Server…
Oct 14 22:00:29 mydomain coturn[9990]: coturn disabled in /etc/default/coturn: turnserver.
Oct 14 22:00:29 mydomain coturn[9990]: See /etc/default/coturn for instructions on enabling: turnserver.
Oct 14 22:00:29 mydomain systemd[1]: Started LSB: coturn TURN Server.
Oct 14 22:00:30 mydomain systemd[1]: Reloading.
Oct 14 22:00:50 mydomain systemd[1]: Reloading Fail2Ban Service.
Oct 14 22:00:58 mydomain systemd[1]: Reloaded Fail2Ban Service.
Oct 14 22:01:01 mydomain systemd[1]: Reloading Fail2Ban Service.
Oct 14 22:01:12 mydomain systemd[1]: Reloaded Fail2Ban Service.
Oct 14 22:01:15 mydomain systemd[1]: Reloading Fail2Ban Service.
Oct 14 22:01:26 mydomain systemd[1]: Reloaded Fail2Ban Service.
Oct 14 22:01:37 mydomain systemd[1]: Reloading.
Oct 14 22:01:37 mydomain systemd[1]: Reloading.
Oct 14 22:01:52 mydomain systemd[1]: Reloading A high performance web server and a reverse proxy server.
Oct 14 22:01:53 mydomain systemd[1]: Reloaded A high performance web server and a reverse proxy server.
Oct 14 22:01:53 mydomain systemd[1]: Starting coturn…
Oct 14 22:01:53 mydomain turnserver[12093]: Cannot open DH file: No such file or directory
Oct 14 22:01:53 mydomain turnserver[12093]: Cannot open DH file: No such file or directory
Oct 14 22:01:53 mydomain turnserver[12093]: Cannot open DH file: No such file or directory
Oct 14 22:01:53 mydomain turnserver[12093]: Cannot open DH file: No such file or directory
Oct 14 22:01:53 mydomain turnserver[12093]: Cannot open DH file: No such file or directory
Oct 14 22:01:53 mydomain systemd[1]: Started coturn.
Oct 14 22:01:53 mydomain systemd[1]: Starting Synapse Matrix homeserver…
Oct 14 22:01:53 mydomain systemd[12114]: matrix-synapse.service: Failed at step EXEC spawning /opt/yunohost/matrix-synapse/bin/python: Exec format error
Oct 14 22:01:53 mydomain systemd[1]: matrix-synapse.service: Control process exited, code=exited status=203
Oct 14 22:01:53 mydomain systemd[1]: Failed to start Synapse Matrix homeserver.
Oct 14 22:01:53 mydomain systemd[1]: matrix-synapse.service: Unit entered failed state.
Oct 14 22:01:53 mydomain systemd[1]: matrix-synapse.service: Failed with result ‘exit-code’.
Oct 14 22:01:54 mydomain nslcd[891]: [e3dfe6] <passwd=“ynh*”> request denied by validnames option
Oct 14 22:01:56 mydomain systemd[1]: matrix-synapse.service: Service hold-off time over, scheduling restart.
Oct 14 22:01:56 mydomain systemd[1]: Stopped Synapse Matrix homeserver.
Oct 14 22:01:56 mydomain systemd[1]: Starting Synapse Matrix homeserver…
Oct 14 22:01:56 mydomain systemd[12195]: matrix-synapse.service: Failed at step EXEC spawning /opt/yunohost/matrix-synapse/bin/python: Exec format error
Oct 14 22:01:56 mydomain systemd[1]: matrix-synapse.service: Control process exited, code=exited status=203
Oct 14 22:01:56 mydomain systemd[1]: Failed to start Synapse Matrix homeserver.
Oct 14 22:01:56 mydomain systemd[1]: matrix-synapse.service: Unit entered failed state.
Oct 14 22:01:56 mydomain systemd[1]: matrix-synapse.service: Failed with result ‘exit-code’.
Oct 14 22:01:57 mydomain systemd[1]: Stopped Synapse Matrix homeserver.
Oct 14 22:01:57 mydomain systemd[1]: Reloading.
Oct 14 22:01:57 mydomain systemd[1]: Starting Daily apt download activities…
Oct 14 22:01:58 mydomain systemd[1]: Reloading.
Oct 14 22:01:58 mydomain systemd[1]: Stopping coturn…
Oct 14 22:01:58 mydomain systemd[1]: Stopped coturn.
Oct 14 22:01:58 mydomain systemd[1]: Reloading.
Oct 14 22:01:59 mydomain systemd[1]: Reloading.
Oct 14 22:02:02 mydomain systemd[1]: Started Daily apt download activities.
Oct 14 22:02:02 mydomain systemd[1]: apt-daily.timer: Adding 7h 4min 32.328939s random time.
Oct 14 22:02:02 mydomain systemd[1]: apt-daily.timer: Adding 35min 31.326410s random time.
Oct 14 22:02:03 mydomain systemd[1]: Reloading Fail2Ban Service.
Oct 14 22:02:15 mydomain systemd[1]: Reloaded Fail2Ban Service.
Oct 14 22:02:18 mydomain systemd[1]: Reloading Fail2Ban Service.
Oct 14 22:02:29 mydomain systemd[1]: Reloaded Fail2Ban Service.
Oct 14 22:02:33 mydomain systemd[1]: Reloading Fail2Ban Service.
Oct 14 22:02:44 mydomain systemd[1]: Reloaded Fail2Ban Service.
Oct 14 22:02:52 mydomain systemd[1]: Reloading.
Oct 14 22:02:52 mydomain systemd[1]: Stopping LSB: coturn TURN Server…
Oct 14 22:02:52 mydomain coturn[13313]: Stopping coturn: turnserver.
Oct 14 22:02:52 mydomain systemd[1]: Stopped LSB: coturn TURN Server.
Oct 14 22:02:53 mydomain systemd[1]: Reloading.
Oct 14 22:03:07 mydomain systemd[1]: Reloading.
Oct 14 22:03:07 mydomain systemd[1]: Reloading.
Oct 14 22:03:08 mydomain systemd[1]: Reloading.
Oct 14 22:09:07 mydomain systemd[1]: Starting Clean php session files…
Oct 14 22:09:07 mydomain systemd[1]: Started Clean php session files.

I guess the important line is the following:

Oct 14 22:01:56 mydomain systemd[12195]: matrix-synapse.service: Failed at step EXEC spawning /opt/yunohost/matrix-synapse/bin/python: Exec format error

So I did try to run /opt/yunohost/matrix-synapse/bin/python, which gives:

bash: ./python: cannot execute binary file: Exec format error

Looking on the web how to solved this, I run file /opt/yunohost/matrix-synapse/bin/python, which gives:

./python: ELF 32-bit LSB shared object, ARM, EABI5 version 1 (SYSV), dynamically linked, interpreter /lib/ld-linux-armhf.so.3, for GNU/Linux 3.2.0, BuildID[sha1]=33a2bd0786c4fe4fa40f029319ceb4738cec9b82, stripped

And then haha ! It mentionned an ARM file ! Indeed, the backup was made from a raspberry, then to be restore on a amd64.

Do you have and idea from here ?

Uuuuh yea … Well that’s tricky … Hmm, I guess you could try to hack the archive by replacing this python binary by some amd64 python binary - but I wouldn’t be surprised that you get some other issues later on because of other file and similar symptoms

Ok, thank you. I will update my issue on github to see if @Josue have an idea.