ikifar2012 / remote-backup-addon

Automatically create and backup HA snapshots using SCP
30 stars 4 forks source link

Backup suddenly stopped working #84

Closed alexz707 closed 1 year ago

alexz707 commented 1 year ago

Happy new year everyone!

I've just looked in my Home Assistent logs and saw that the last backup (automatic backup -> mo, wed, fri at 0200) was not successful. The addon should copy from home assistant to my diskstation (synology).

I did neither change/update something on home assistent nor on my diskstation.

I get the following error when I try to make a backup:

s6-rc: info: service s6rc-oneshot-runner: starting
s6-rc: info: service s6rc-oneshot-runner successfully started
s6-rc: info: service base-addon-banner: starting
-----------------------------------------------------------
 Add-on: Remote Backup
 Automatically create and transfer HA backups using SFTP (SCP), rsync, or rclone (experimental)
-----------------------------------------------------------
 Add-on version: 2022.12.0
 You are running the latest version of this add-on.
 System: Home Assistant OS 9.4  (armv7 / raspberrypi3)
 Home Assistant Core: 2022.12.8
 Home Assistant Supervisor: 2022.12.1
-----------------------------------------------------------
 Please, share the above information when looking for help
 or support in, e.g., GitHub, forums or the Discord chat.
-----------------------------------------------------------
s6-rc: info: service base-addon-banner successfully started
s6-rc: info: service fix-attrs: starting
s6-rc: info: service base-addon-log-level: starting
s6-rc: info: service fix-attrs successfully started
s6-rc: info: service base-addon-log-level successfully started
s6-rc: info: service legacy-cont-init: starting
s6-rc: info: service legacy-cont-init successfully started
s6-rc: info: service legacy-services: starting
s6-rc: info: service legacy-services successfully started
[15:30:08] WARNING: 
[15:30:08] WARNING: Setting a password is highly recommended!
[15:30:08] WARNING: 
[15:30:08] WARNING: Please set a password in the 'backup_password' option.
[15:30:08] WARNING: 
[15:30:08] WARNING: If unsure, check the add-on manual for more information.
[15:30:08] WARNING: 
[15:30:10] INFO: Adding SSH configuration.
[15:30:11] INFO: Creating non-encrypted full backup: "Automated backup 2023-01-01 15-30"
[15:32:27] INFO: Backup created: d09a3786
[15:32:28] INFO: Copying backup using SFTP/SCP.
scp: dest open ""/NetBackup/Hassio/Automated backup 2023-01-01 15-30.tar"": No such file or directory

scp: failed to upload file /backup/d09a3786.tar to "/NetBackup/Hassio/Automated backup 2023-01-01 15-30.tar"

[15:32:31] WARNING: SFTP transfer failed, falling back to SCP: Invalid command line argument
Permission denied, please try again.
lost connection
[15:32:32] ERROR: Error copying backup d09a3786.tar to /NetBackup/Hassio on diskone.homesys:  Invalid command line argument
[15:32:37] NOTICE: Deleting local backup: ff010044
[15:32:38] INFO: Backup process done!
s6-rc: info: service legacy-services: stopping
s6-rc: info: service legacy-services successfully stopped
s6-rc: info: service legacy-cont-init: stopping
s6-rc: info: service legacy-cont-init successfully stopped
s6-rc: info: service fix-attrs: stopping
s6-rc: info: service base-addon-log-level: stopping
s6-rc: info: service base-addon-log-level successfully stopped
s6-rc: info: service fix-attrs successfully stopped
s6-rc: info: service base-addon-banner: stopping
s6-rc: info: service base-addon-banner successfully stopped
s6-rc: info: service s6rc-oneshot-runner: stopping
s6-rc: info: service s6rc-oneshot-runner successfully stopped

When I try to sftp or scp from the terminal in HA I can send files to the diskstation:

scp -i /ssl/diskOneHassio -v 3ffa4a73.tar hassio@diskone.homesys:/NetBackup/Hassio/test.tar

works as well as

sftp -i /ssl/diskOneHassio hassio@diskone.homesys
sftp> put 3ffa4a73.tar 
Uploading 3ffa4a73.tar to /NetBackup/Hassio/3ffa4a73.tar

My config looks like this:

backup_custom_prefix: Automated backup
backup_friendly_name: true
backup_keep_local: "10"
remote_host: diskone.homesys
remote_key: diskOneHassio
remote_port: 22
remote_user: hassio
rsync_enabled: false
rsync_exclude:
  - /config/*.db-shm
  - /config/*.db-wal
  - /config/*.db
rsync_rootfolder: hassio-sync
ssh_enabled: true
ssh_remote_directory: /NetBackup/Hassio

The debug output would be like this: (seems to be only the end of the output, I don't know how I can retrieve the full log, this is what I got when I download the file from the GUI)):

debug1: Connecting to diskone.homesys [10.77.71.10] port 22.
debug1: Connection established.
debug1: identity file /root/.ssh/id_rsa type 0
debug1: identity file /root/.ssh/id_rsa-cert type -1
debug1: Local version string SSH-2.0-OpenSSH_9.1
debug1: Remote protocol version 2.0, remote software version OpenSSH_8.2
debug1: compat_banner: match: OpenSSH_8.2 pat OpenSSH* compat 0x04000000
debug1: Authenticating to diskone.homesys:22 as 'hassio'
debug1: load_hostkeys: fopen /root/.ssh/known_hosts2: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts2: No such file or directory
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug1: kex: algorithm: curve25519-sha256
debug1: kex: host key algorithm: ssh-ed25519
debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none
debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none
debug1: expecting SSH2_MSG_KEX_ECDH_REPLY
debug1: SSH2_MSG_KEX_ECDH_REPLY received
debug1: Server host key: ssh-ed25519 SHA256:iEzfsoc4rYj047xxHTMbZSxtNOAVYdZLZAE7GVPsMxs
debug1: load_hostkeys: fopen /root/.ssh/known_hosts2: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts2: No such file or directory
debug1: Host 'diskone.homesys' is known and matches the ED25519 host key.
debug1: Found key in /root/.ssh/known_hosts:3
debug1: rekey out after 134217728 blocks
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug1: SSH2_MSG_NEWKEYS received
debug1: rekey in after 134217728 blocks
debug1: Will attempt key: /root/.ssh/id_rsa RSA SHA256:d/t020YtXCuwRBp04lAzEDV7Rwywxof3yNqOoJVo7/Q explicit
debug1: SSH2_MSG_EXT_INFO received
debug1: kex_input_ext_info: server-sig-algs=<ssh-ed25519,sk-ssh-ed25519@openssh.com,ssh-rsa,rsa-sha2-256,rsa-sha2-512,ssh-dss,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,sk-ecdsa-sha2-nistp256@openssh.com>
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug1: Authentications that can continue: publickey,password
debug1: Next authentication method: publickey
debug1: Offering public key: /root/.ssh/id_rsa RSA SHA256:d/t020YtXCuwRBp04lAzEDV7Rwywxof3yNqOoJVo7/Q explicit
debug1: Server accepts key: /root/.ssh/id_rsa RSA SHA256:d/t020YtXCuwRBp04lAzEDV7Rwywxof3yNqOoJVo7/Q explicit
Authenticated to diskone.homesys ([10.77.71.10]:22) using "publickey".
debug1: channel 0: new [client-session]
debug1: Requesting no-more-sessions@openssh.com
debug1: Entering interactive session.
debug1: pledge: filesystem
debug1: client_input_global_request: rtype hostkeys-00@openssh.com want_reply 0
debug1: client_input_hostkeys: searching /root/.ssh/known_hosts for diskone.homesys / (none)
debug1: client_input_hostkeys: searching /root/.ssh/known_hosts2 for diskone.homesys / (none)
debug1: client_input_hostkeys: hostkeys file /root/.ssh/known_hosts2 does not exist
debug1: client_input_hostkeys: no new or deprecated keys from server
debug1: Remote: /var/services/homes/hassio/.ssh/authorized_keys:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
debug1: Remote: /var/services/homes/hassio/.ssh/authorized_keys:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
debug1: Sending command: scp -v -t "/NetBackup/Hassio/Automated backup 2023-01-01 16-00.tar"
Permission denied, please try again.
lost connection
debug1: client_input_channel_req: channel 0 rtype exit-status reply 0
debug1: client_input_channel_req: channel 0 rtype eow@openssh.com reply 0
debug1: channel 0: free: client-session, nchannels 1
Killed by signal 1.
[16:03:02] ERROR: Error copying backup 4e4b9218.tar to /NetBackup/Hassio on diskone.homesys:  Invalid command line argument
[16:03:03] DEBUG: Rsync disabled.
[16:03:03] DEBUG: Rclone disabled.
[16:03:04] DEBUG: Requested API resource: http://supervisor/backups/reload
[16:03:04] DEBUG: Request method: POST
[16:03:04] DEBUG: Request data: {}
[16:03:04] DEBUG: API HTTP Response code: 200
[16:03:04] DEBUG: API Response: {"result": "ok", "data": {}}
[16:03:05] DEBUG: Requested API resource: http://supervisor/backups
[16:03:05] DEBUG: Request method: GET
[16:03:05] DEBUG: Request data: {}
[16:03:05] DEBUG: API HTTP Response code: 200
[16:03:05] DEBUG: API Response: {"result": "ok", "data": {"backups": [{"slug": "b77e2531", "name": "Automated backup 2023-01-01 14-46", "date": "2023-01-01T13:46:28.468190+00:00", "type": "full", "size": 32.42, "protected": false, "compressed": true, "content": {"homeassistant": true, "addons": ["a0d7b954_nodered", "core_configurator", "a0d7b954_ide", "core_duckdns", "core_mariadb", "a0d7b954_traccar", "core_ssh", "3490a758_remote_backup", "a0d7b954_phpmyadmin", "a0d7b954_zwavejs2mqtt", "core_mosquitto"], "folders": ["share", "addons/local", "ssl", "media"]}}, {"slug": "d97fee2c", "name": "Automated backup 2023-01-01 15-08", "date": "2023-01-01T14:09:01.811434+00:00", "type": "full", "size": 32.56, "protected": false, "compressed": true, "content": {"homeassistant": true, "addons": ["a0d7b954_nodered", "core_configurator", "a0d7b954_ide", "core_duckdns", "core_mariadb", "a0d7b954_traccar", "core_ssh", "3490a758_remote_backup", "a0d7b954_phpmyadmin", "a0d7b954_zwavejs2mqtt", "core_mosquitto"], "folders": ["share", "addons/local", "ssl", "media"]}}, {"slug": "55657f6e", "name": "Automated backup 2023-01-01 15-16", "date": "2023-01-01T14:16:35.122465+00:00", "type": "full", "size": 32.6, "protected": false, "compressed": true, "content": {"homeassistant": true, "addons": ["a0d7b954_nodered", "core_configurator", "a0d7b954_ide", "core_duckdns", "core_mariadb", "a0d7b954_traccar", "core_ssh", "3490a758_remote_backup", "a0d7b954_phpmyadmin", "a0d7b954_zwavejs2mqtt", "core_mosquitto"], "folders": ["share", "addons/local", "ssl", "media"]}}, {"slug": "65d8ce68", "name": "Automated backup 2022-12-28 02-00", "date": "2022-12-28T01:00:35.075020+00:00", "type": "full", "size": 30.09, "protected": false, "compressed": true, "content": {"homeassistant": true, "addons": ["a0d7b954_nodered", "core_configurator", "a0d7b954_ide", "core_duckdns", "core_mariadb", "a0d7b954_traccar", "core_ssh", "3490a758_remote_backup", "a0d7b954_phpmyadmin", "a0d7b954_zwavejs2mqtt"], "folders": ["share", "addons/local", "ssl", "media"]}}, {"slug": "8e13edfa", "name": "addon_a0d7b954_zwavejs2mqtt_1.4.1", "date": "2022-12-28T19:29:58.037063+00:00", "type": "partial", "size": 0.78, "protected": false, "compressed": true, "content": {"homeassistant": false, "addons": ["a0d7b954_zwavejs2mqtt"], "folders": []}}, {"slug": "d09a3786", "name": "Automated backup 2023-01-01 15-30", "date": "2023-01-01T14:30:12.003679+00:00", "type": "full", "size": 32.67, "protected": false, "compressed": true, "content": {"homeassistant": true, "addons": ["a0d7b954_nodered", "core_configurator", "a0d7b954_ide", "core_duckdns", "core_mariadb", "a0d7b954_traccar", "core_ssh", "3490a758_remote_backup", "a0d7b954_phpmyadmin", "a0d7b954_zwavejs2mqtt", "core_mosquitto"], "folders": ["share", "addons/local", "ssl", "media"]}}, {"slug": "d0113eb7", "name": "Automated backup 2023-01-01 02-00", "date": "2023-01-01T01:00:24.362513+00:00", "type": "full", "size": 30.96, "protected": false, "compressed": true, "content": {"homeassistant": true, "addons": ["a0d7b954_nodered", "core_configurator", "a0d7b954_ide", "core_duckdns", "core_mariadb", "a0d7b954_traccar", "core_ssh", "3490a758_remote_backup", "a0d7b954_phpmyadmin", "a0d7b954_zwavejs2mqtt", "core_mosquitto"], "folders": ["share", "addons/local", "ssl", "media"]}}, {"slug": "3ffa4a73", "name": "addon_3490a758_remote_backup_2022.9.4", "date": "2022-12-30T10:53:15.946897+00:00", "type": "partial", "size": 0.01, "protected": false, "compressed": true, "content": {"homeassistant": false, "addons": ["3490a758_remote_backup"], "folders": []}}, {"slug": "a9320c51", "name": "Automated backup 2023-01-01 14-25", "date": "2023-01-01T13:25:11.170762+00:00", "type": "full", "size": 32.29, "protected": false, "compressed": true, "content": {"homeassistant": true, "addons": ["a0d7b954_nodered", "core_configurator", "a0d7b954_ide", "core_duckdns", "core_mariadb", "a0d7b954_traccar", "core_ssh", "3490a758_remote_backup", "a0d7b954_phpmyadmin", "a0d7b954_zwavejs2mqtt", "core_mosquitto"], "folders": ["share", "addons/local", "ssl", "media"]}}, {"slug": "4e4b9218", "name": "Automated backup 2023-01-01 16-00", "date": "2023-01-01T15:00:34.895926+00:00", "type": "full", "size": 32.8, "protected": false, "compressed": true, "content": {"homeassistant": true, "addons": ["a0d7b954_nodered", "core_configurator", "a0d7b954_ide", "core_duckdns", "core_mariadb", "a0d7b954_traccar", "core_ssh", "3490a758_remote_backup", "a0d7b954_phpmyadmin", "a0d7b954_zwavejs2mqtt", "core_mosquitto"], "folders": ["share", "addons/local", "ssl", "media"]}}, {"slug": "7609b46a", "name": "Automated backup 2022-12-30 02-00", "date": "2022-12-30T01:00:20.210418+00:00", "type": "full", "size": 30.01, "protected": false, "compressed": true, "content": {"homeassistant": true, "addons": ["a0d7b954_nodered", "core_configurator", "a0d7b954_ide", "core_duckdns", "core_mariadb", "a0d7b954_traccar", "core_ssh", "3490a758_remote_backup", "a0d7b954_phpmyadmin", "a0d7b954_zwavejs2mqtt"], "folders": ["share", "addons/local", "ssl", "media"]}}]}}
[16:03:08] NOTICE: Deleting local backup: 65d8ce68
[16:03:08] DEBUG: Requested API resource: http://supervisor/backups/65d8ce68
[16:03:08] DEBUG: Request method: DELETE
[16:03:08] DEBUG: Request data: {}
[16:03:08] DEBUG: API HTTP Response code: 200
[16:03:08] DEBUG: API Response: {"result": "ok", "data": {}}
[16:03:10] INFO: Backup process done!
[16:03:10] DEBUG: Requested API resource: http://supervisor/core/api/events/remote_backup_status
[16:03:10] DEBUG: Request method: POST
[16:03:10] DEBUG: Request data: {"result":"ok","message:":"Backup Automated backup 2023-01-01 16-00 created."}
[16:03:10] DEBUG: API HTTP Response code: 200
[16:03:10] DEBUG: API Response: {"message":"Event remote_backup_status fired."}
s6-rc: info: service legacy-services: stopping
s6-rc: info: service legacy-services successfully stopped
s6-rc: info: service legacy-cont-init: stopping
s6-rc: info: service legacy-cont-init successfully stopped
s6-rc: info: service fix-attrs: stopping
s6-rc: info: service base-addon-log-level: stopping
s6-rc: info: service fix-attrs successfully stopped
s6-rc: info: service base-addon-log-level successfully stopped
s6-rc: info: service base-addon-banner: stopping
s6-rc: info: service base-addon-banner successfully stopped
s6-rc: info: service s6rc-oneshot-runner: stopping
s6-rc: info: service s6rc-oneshot-runner successfully stopped

Do you have an idea what going on? Regards Alex

SirGoodenough commented 1 year ago

My take, that looks like a key problem. I would set-up a new key and try that. some helpful (to me) links... https://github.com/ikifar2012/remote-backup-addon/issues/82#issuecomment-1346995512

Roos-AID commented 1 year ago

I have done a clean install and have exactly the same problem.
Config : HA on Yellow , Synology NAS I can do scp from terminal in HA, so key must be valid.
Also tried with the password option, this works as well when done from terminal. When configured in HA in the config file for automated backup it also fails with same error.

Can this be caused by the latest update to the code ? It seems that the command syntax for scp now includes \ in file name .

SirGoodenough commented 1 year ago

Guess what...

a0d7b954_plex
[06:26:32] INFO: Backup created: 0e37b5fa
[06:26:32] INFO: Copying backup using SFTP/SCP.
scp: dest open ""/media/pi/RecoveryBuffalo/Backups/HASupervised/ChaloupkaAbode_backup 2023-01-01 06-18.tar"": No such file or directory

scp: failed to upload file /backup/0e37b5fa.tar to "/media/pi/RecoveryBuffalo/Backups/HASupervised/ChaloupkaAbode_backup 2023-01-01 06-18.tar"

[06:26:33] WARNING: SFTP transfer failed, falling back to SCP: Invalid command line argument
[06:27:16] NOTICE: Deleting local backup: c148ef9d
[06:27:18] INFO: Backup process done!

I see it also. I am not synology, just feeding into a drive on a PI. It is my imagination, or is there double quotes in there...

ikifar2012 commented 1 year ago

I think this may just be a logging issue, notice how it fell back to SCP, check to see if it actually transferred the backup to the remote destination

patman15 commented 1 year ago

@ikifar2012 there is an issue, unfortunately and it is the double quotes. Just reproduced it and it is as in the first post of @alexz707. I have no idea why the double quotes have worked before (I even think they were necessary).

ikifar2012 commented 1 year ago

@patman15 interesting this didn't show in my testing, the reason they were there originally I remember there being an issue with spaces in paths

patman15 commented 1 year ago

I have no idea why it stopped working but removing the double quotes helps. I tried to go back and forward to reproduce the issue, but now it is only working without the double quotes. No idea what changed. I have a fix, but messed up the config stuff, so can't provide a PR soon.

alexz707 commented 1 year ago

I think this may just be a logging issue, notice how it fell back to SCP, check to see if it actually transferred the backup to the remote destination

unfortunatley the files do not get transfered.

stale[bot] commented 1 year ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

ikifar2012 commented 1 year ago

I am going to consider this solved, feel free to re-open if you have any issues