M-Welsch commented 8 months ago

Description

conduct a real backup

What happens if we don't do it (aka Why is it important)?

we want to close the mvp and thereby have a minimally working product that we can put aside without having bad feelings. This serves then as a basis for future improvements

Definition of Ready

[x] have the raspi 4
[x] have a usb-sata bridge
[x] have a hardlink-copy from the latest existing backup on the hard drive

Key Tasks

[x] put the software on the raspi 4
[x] configure it all (linux stuff)
[x] set wait-time between backups to 12h for
[x] power it on
[x] let it run for 3 days
[x] check if backup is integer
[x] check logs

Acceptance Criteria

[x] backup ran sucessfully

M-Welsch commented 7 months ago

currently blocked by #33

M-Welsch commented 7 months ago

blocked by

Jan 20 23:00:04 basehw4sn2 python3[1523]: 2024-01-20 23:00:04,429 DEBUG: __main__: Mounting HDD...
Jan 20 23:00:04 basehw4sn2 python3[1528]: mount: /media/BackupHDD: must be superuser to use mount.
Jan 20 23:00:04 basehw4sn2 python3[1528]:        dmesg(1) may have more information after failed mount system call.
Jan 20 23:00:04 basehw4sn2 python3[1531]: Pseudo-terminal will not be allocated because stdin is not a terminal.
Jan 20 23:00:04 basehw4sn2 python3[1523]: 2024-01-20 23:00:04,459 DEBUG: __main__: obtained IP Address of NAS: 192.168.0.2
Jan 20 23:00:04 basehw4sn2 python3[1523]: 2024-01-20 23:00:04,459 DEBUG: __main__: Backing up with command rsync -aH --stats --delete 192.168.0.2::backup_data_source/* /media/BackupHDD/backups/current
Jan 20 23:00:04 basehw4sn2 python3[1523]: 2024-01-20 23:00:04,463 INFO: __main__: Starting Backup...
Jan 20 23:00:04 basehw4sn2 python3[1523]: 2024-01-20 23:00:04,579 INFO: __main__: Backup finished.
Jan 20 23:00:04 basehw4sn2 python3[1523]: 2024-01-20 23:00:04,579 DEBUG: __main__: Backup output task finished.
Jan 20 23:00:04 basehw4sn2 python3[1523]: 2024-01-20 23:00:04,579 ERROR: __main__: Fehlerausgabe: rsync: [Receiver] mkdir "/media/BackupHDD/backups/current" failed: No such file or directory (2)
Jan 20 23:00:04 basehw4sn2 python3[1523]: rsync error: error in file IO (code 11) at main.c(791) [Receiver=3.2.7]
Jan 20 23:00:04 basehw4sn2 python3[1523]: 2024-01-20 23:00:04,579 INFO: __main__: Disconnecting Backup HDD

have to investigate

M-Welsch commented 7 months ago

turned out that https://github.com/M-Welsch/backup-server/blob/63b6059b673297c73210776ea0d5ae5afd555763/software/bcu/__main__.py#L61 would have to change to (using shell=True), but I don't know why

        subprocess.call("mount /dev/BACKUPHDD", shell=True)  # Todo: why do I have to use the shell here??

M-Welsch commented 7 months ago

First run. Logs are not of particular importance, just to have them somewhere around

Jan 21 11:02:38 basehw4sn2 python3[1068]: 2024-01-21 11:02:38,148 INFO: __main__: Connect Backup HDD
Jan 21 11:02:38 basehw4sn2 python3[1068]: 2024-01-21 11:02:38,149 DEBUG: __main__: Docking...
Jan 21 11:02:41 basehw4sn2 python3[1068]: 2024-01-21 11:02:41,167 WARNING: __main__: couldn't dock, try another time.
Jan 21 11:02:44 basehw4sn2 python3[1068]: 2024-01-21 11:02:44,190 DEBUG: __main__: Switching HDD power on...
Jan 21 11:02:55 basehw4sn2 python3[1068]: 2024-01-21 11:02:55,707 DEBUG: __main__: Mounting HDD...
Jan 21 11:02:55 basehw4sn2 python3[1077]: mount: /media/BackupHDD: must be superuser to use mount.
Jan 21 11:02:55 basehw4sn2 python3[1077]:        dmesg(1) may have more information after failed mount system call.
Jan 21 11:03:00 basehw4sn2 python3[1068]: 2024-01-21 11:03:00,728 WARNING: __main__: mounting of backupHDD failed, try another time
Jan 21 11:03:06 basehw4sn2 python3[1098]: Pseudo-terminal will not be allocated because stdin is not a terminal.
Jan 21 11:03:06 basehw4sn2 python3[1068]: 2024-01-21 11:03:06,035 DEBUG: __main__: obtained IP Address of NAS: 192.168.0.2
Jan 21 11:03:06 basehw4sn2 python3[1068]: 2024-01-21 11:03:06,035 DEBUG: __main__: Backing up with command rsync -aH --stats --delete 192.168.0.2::backup_data_source/* /media/BackupHDD/backups/current
Jan 21 11:03:06 basehw4sn2 python3[1068]: 2024-01-21 11:03:06,040 INFO: __main__: Starting Backup...
Jan 21 11:05:02 basehw4sn2 python3[1068]: 2024-01-21 11:05:02,909 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/21af8d916fe354465a7de2b90c82064466943a566bb354763458a2cf8bfd0b8e-init/work/work/#45"
Jan 21 11:05:44 basehw4sn2 python3[1068]: 2024-01-21 11:05:44,215 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/3c42bedd10eb9960b5bca04cb761ed20f18fd3b349374b1182d4d447f93e250c-init/work/work/#14"
Jan 21 11:07:06 basehw4sn2 python3[1068]: 2024-01-21 11:07:06,823 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/42f0d5d6dce71c39c53cea3a5f09ade87ac7e88ff980e2311879da5f654509f5-init/work/work/#22"
Jan 21 11:07:13 basehw4sn2 python3[1068]: 2024-01-21 11:07:13,091 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/57a3c63b8a8139710205d2dc1225a9e031fcfdc51f4c5aac4339d062c75d7255/diff/usr/src/arm-alignment.patch"
Jan 21 11:07:13 basehw4sn2 python3[1068]: 2024-01-21 11:07:13,092 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/57a3c63b8a8139710205d2dc1225a9e031fcfdc51f4c5aac4339d062c75d7255/diff/usr/src/asynctio_unix_events.patch"
Jan 21 11:07:13 basehw4sn2 python3[1068]: 2024-01-21 11:07:13,092 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/57a3c63b8a8139710205d2dc1225a9e031fcfdc51f4c5aac4339d062c75d7255/diff/usr/src/fix-xattrs-glibc.patch"
Jan 21 11:07:13 basehw4sn2 python3[1068]: 2024-01-21 11:07:13,092 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/57a3c63b8a8139710205d2dc1225a9e031fcfdc51f4c5aac4339d062c75d7255/diff/usr/src/musl-find_library.patch"
Jan 21 11:07:25 basehw4sn2 python3[1068]: 2024-01-21 11:07:25,149 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/6231f558106aff6b98f6a10f102e45d9b06ef7690e065d08c48baf6fbd8be424/diff/usr/src/requirements.txt"
Jan 21 11:07:26 basehw4sn2 python3[1068]: 2024-01-21 11:07:26,451 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/75c11afb9bcbaf1965bee540af40c9b49061dbcbe33869fee3b96d59470d3eb0-init/work/work/#41"
Jan 21 11:07:27 basehw4sn2 python3[1068]: 2024-01-21 11:07:27,833 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/7ecca733b5cce3eb5fa22ca6aa5769e89930091426dcbf6673daac83a7142b6d-init/work/work/#4f"
Jan 21 11:07:39 basehw4sn2 python3[1068]: 2024-01-21 11:07:39,246 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/7ecca733b5cce3eb5fa22ca6aa5769e89930091426dcbf6673daac83a7142b6d/work/work/#1c"
Jan 21 11:07:49 basehw4sn2 python3[1068]: 2024-01-21 11:07:49,606 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/9b0cd1b17f2f3f8808c72add8512440f43736952e819c37805ddaf412db02f74/diff/usr/src/telldus-fix-gcc-11-issues.patch"
Jan 21 11:07:50 basehw4sn2 python3[1068]: 2024-01-21 11:07:50,910 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/a09b99a2a0020d22034f41e2743690d1da12760dbef0465e55224355970565d4-init/work/work/#5b"
Jan 21 11:08:08 basehw4sn2 python3[1068]: 2024-01-21 11:08:08,345 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/d0402d66df200c9e9acc18de08261cf1cf43eea0acfdd73c60b5046cb595993d/diff/usr/src/libcec-fix-null-return.patch"
Jan 21 11:08:11 basehw4sn2 python3[1068]: 2024-01-21 11:08:11,938 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/e38fd4115d660a4ddc201c59327a72a5c403597937d9c3043a027ccc5b143b41-init/work/work/#4b8"
Jan 21 11:08:24 basehw4sn2 python3[1068]: 2024-01-21 11:08:24,366 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/volumes/backingFsBlockDev"
Jan 21 11:50:37 basehw4sn2 python3[1068]: 2024-01-21 11:50:37,420 DEBUG: __main__: Live Output:
Jan 21 11:50:37 basehw4sn2 python3[1068]: 2024-01-21 11:50:37,433 DEBUG: __main__: Live Output: Number of files: 1,975,449 (reg: 1,666,118, dir: 293,388, link: 15,923, special: 20)
Jan 21 11:50:37 basehw4sn2 python3[1068]: 2024-01-21 11:50:37,433 DEBUG: __main__: Live Output: Number of created files: 85,862 (reg: 71,320, dir: 13,270, link: 1,270, special: 2)
Jan 21 11:50:37 basehw4sn2 python3[1068]: 2024-01-21 11:50:37,436 DEBUG: __main__: Live Output: Number of deleted files: 5,181 (reg: 4,468, dir: 713)
Jan 21 11:50:37 basehw4sn2 python3[1068]: 2024-01-21 11:50:37,436 DEBUG: __main__: Live Output: Number of regular files transferred: 71,168
Jan 21 11:50:37 basehw4sn2 python3[1068]: 2024-01-21 11:50:37,437 DEBUG: __main__: Live Output: Total file size: 2,431,742,601,863 bytes
Jan 21 11:50:37 basehw4sn2 python3[1068]: 2024-01-21 11:50:37,437 DEBUG: __main__: Live Output: Total transferred file size: 55,386,958,910 bytes
Jan 21 11:50:37 basehw4sn2 python3[1068]: 2024-01-21 11:50:37,438 DEBUG: __main__: Live Output: Literal data: 54,371,042,643 bytes
Jan 21 11:50:37 basehw4sn2 python3[1068]: 2024-01-21 11:50:37,438 DEBUG: __main__: Live Output: Matched data: 1,015,916,267 bytes
Jan 21 11:50:37 basehw4sn2 python3[1068]: 2024-01-21 11:50:37,438 DEBUG: __main__: Live Output: File list size: 43,143,750
Jan 21 11:50:37 basehw4sn2 python3[1068]: 2024-01-21 11:50:37,438 DEBUG: __main__: Live Output: File list generation time: 0.001 seconds
Jan 21 11:50:37 basehw4sn2 python3[1068]: 2024-01-21 11:50:37,439 DEBUG: __main__: Live Output: File list transfer time: 0.000 seconds
Jan 21 11:50:37 basehw4sn2 python3[1068]: 2024-01-21 11:50:37,439 DEBUG: __main__: Live Output: Total bytes sent: 3,918,600
Jan 21 11:50:37 basehw4sn2 python3[1068]: 2024-01-21 11:50:37,439 DEBUG: __main__: Live Output: Total bytes received: 54,448,596,703
Jan 21 11:50:37 basehw4sn2 python3[1068]: 2024-01-21 11:50:37,439 DEBUG: __main__: Live Output:
Jan 21 11:50:37 basehw4sn2 python3[1068]: 2024-01-21 11:50:37,439 DEBUG: __main__: Live Output: sent 3,918,600 bytes  received 54,448,596,703 bytes  19,096,095.14 bytes/sec
Jan 21 11:50:37 basehw4sn2 python3[1068]: 2024-01-21 11:50:37,439 DEBUG: __main__: Live Output: total size is 2,431,742,601,863  speedup is 44.66
Jan 21 11:50:37 basehw4sn2 python3[1068]: 2024-01-21 11:50:37,504 INFO: __main__: Backup finished.
Jan 21 11:50:37 basehw4sn2 python3[1068]: 2024-01-21 11:50:37,504 DEBUG: __main__: Backup output task finished.
Jan 21 11:50:37 basehw4sn2 python3[1068]: 2024-01-21 11:50:37,504 ERROR: __main__: Fehlerausgabe: rsync: [sender] read errors mapping "/hdd0/nextcloud_old/martha/files/Bilder/2021_04_23_HedwigOmaZuBesuch/DSC_8486.JPG" (in backup_data_source): Input/output error (5)
Jan 21 11:50:37 basehw4sn2 python3[1068]: rsync: [sender] read errors mapping "/hdd0/nextcloud_old/martha/files/Bilder/2021_04_23_HedwigOmaZuBesuch/DSC_8486.JPG" (in backup_data_source): Input/output error (5)
Jan 21 11:50:37 basehw4sn2 python3[1068]: ERROR: hdd0/nextcloud_old/martha/files/Bilder/2021_04_23_HedwigOmaZuBesuch/DSC_8486.JPG failed verification -- update discarded.
Jan 21 11:50:37 basehw4sn2 python3[1068]: rsync: [sender] read errors mapping "/hdd0/share/MundM/Bilder/2020/2020_10_03-04_Annas_erster_Geburtstag/DSCN5181.JPG" (in backup_data_source): Input/output error (5)
Jan 21 11:50:37 basehw4sn2 python3[1068]: rsync: [sender] read errors mapping "/hdd0/share/MundM/Bilder/2020/2020_10_03-04_Annas_erster_Geburtstag/DSCN5181.JPG" (in backup_data_source): Input/output error (5)
Jan 21 11:50:37 basehw4sn2 python3[1068]: ERROR: hdd0/share/MundM/Bilder/2020/2020_10_03-04_Annas_erster_Geburtstag/DSCN5181.JPG failed verification -- update discarded.
Jan 21 11:50:37 basehw4sn2 python3[1068]: rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1865) [generator=3.2.7]
Jan 21 11:50:37 basehw4sn2 python3[1068]: 2024-01-21 11:50:37,505 INFO: __main__: Disconnecting Backup HDD
Jan 21 11:50:37 basehw4sn2 python3[1068]: 2024-01-21 11:50:37,505 DEBUG: __main__: Unmounting HDD...
Jan 21 11:50:41 basehw4sn2 python3[1068]: 2024-01-21 11:50:41,626 DEBUG: __main__: Switching HDD power off...
Jan 21 11:51:03 basehw4sn2 python3[1068]: 2024-01-21 11:51:03,165 DEBUG: __main__: Undocking...
Jan 21 11:51:07 basehw4sn2 python3[1068]: 2024-01-21 11:51:07,137 INFO: __main__: waiting for 60s before shutdown
Jan 21 11:52:07 basehw4sn2 python3[1068]: 2024-01-21 11:52:07,198 INFO: __main__: Programming PCU. Setting current time and time for next wakeup
Jan 21 11:52:10 basehw4sn2 python3[1068]: 2024-01-21 11:52:10,265 DEBUG: __main__: read current time from pcu: 2024-01-21 11:52:01
Jan 21 11:52:13 basehw4sn2 python3[1068]: 2024-01-21 11:52:13,291 DEBUG: __main__: read wakeup time from pcu: 2024-01-21 23:52:00
Jan 21 11:52:16 basehw4sn2 python3[1068]: 2024-01-21 11:52:16,316 DEBUG: __main__: read backup time from pcu: 2024-01-21 23:52:00
Jan 21 11:52:16 basehw4sn2 python3[1068]: 2024-01-21 11:52:16,317 INFO: __main__: Shutting down...

M-Welsch commented 7 months ago

lots of rsync errors appeared. Not sure if rsync crashed because of them.

2024-01-22 19:01:51,860 DEBUG: __main__: obtained IP Address of NAS: 192.168.0.2
2024-01-22 19:01:51,863 DEBUG: __main__: Backing up with command rsync -aH --stats --delete 192.168.0.2::backup_data_source/* /media/BackupHDD/backups/current
2024-01-22 19:01:51,869 INFO: __main__: Starting Backup...
2024-01-22 19:04:23,550 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/21af8d916fe354465a7de2b90c82064466943a566bb354763458a2cf8bfd0b8e-init/work/work/#45"
2024-01-22 19:04:42,273 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/3c42bedd10eb9960b5bca04cb761ed20f18fd3b349374b1182d4d447f93e250c-init/work/work/#14"
2024-01-22 19:06:04,488 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/42f0d5d6dce71c39c53cea3a5f09ade87ac7e88ff980e2311879da5f654509f5-init/work/work/#22"
2024-01-22 19:06:05,614 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/57a3c63b8a8139710205d2dc1225a9e031fcfdc51f4c5aac4339d062c75d7255/diff/usr/src/arm-alignment.patch"
2024-01-22 19:06:05,615 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/57a3c63b8a8139710205d2dc1225a9e031fcfdc51f4c5aac4339d062c75d7255/diff/usr/src/asynctio_unix_events.patch"
2024-01-22 19:06:05,615 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/57a3c63b8a8139710205d2dc1225a9e031fcfdc51f4c5aac4339d062c75d7255/diff/usr/src/fix-xattrs-glibc.patch"
2024-01-22 19:06:05,615 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/57a3c63b8a8139710205d2dc1225a9e031fcfdc51f4c5aac4339d062c75d7255/diff/usr/src/musl-find_library.patch"
2024-01-22 19:06:18,764 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/6231f558106aff6b98f6a10f102e45d9b06ef7690e065d08c48baf6fbd8be424/diff/usr/src/requirements.txt"
2024-01-22 19:06:21,292 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/75c11afb9bcbaf1965bee540af40c9b49061dbcbe33869fee3b96d59470d3eb0-init/work/work/#41"
2024-01-22 19:06:23,840 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/7ecca733b5cce3eb5fa22ca6aa5769e89930091426dcbf6673daac83a7142b6d-init/work/work/#4f"
2024-01-22 19:06:36,193 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/7ecca733b5cce3eb5fa22ca6aa5769e89930091426dcbf6673daac83a7142b6d/work/work/#12"
2024-01-22 19:06:46,993 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/9b0cd1b17f2f3f8808c72add8512440f43736952e819c37805ddaf412db02f74/diff/usr/src/telldus-fix-gcc-11-issues.patch"
2024-01-22 19:06:48,913 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/a09b99a2a0020d22034f41e2743690d1da12760dbef0465e55224355970565d4-init/work/work/#5b"
2024-01-22 19:06:59,836 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/d0402d66df200c9e9acc18de08261cf1cf43eea0acfdd73c60b5046cb595993d/diff/usr/src/libcec-fix-null-return.patch"
2024-01-22 19:07:02,501 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/overlay2/e38fd4115d660a4ddc201c59327a72a5c403597937d9c3043a027ccc5b143b41-init/work/work/#4b8"
2024-01-22 19:07:16,304 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/volumes/backingFsBlockDev"
2024-01-22 19:37:44,235 DEBUG: __main__: Live Output: 
2024-01-22 19:37:44,236 DEBUG: __main__: Live Output: Number of files: 1,964,660 (reg: 1,657,042, dir: 292,304, link: 15,296, special: 18)
2024-01-22 19:37:44,237 DEBUG: __main__: Live Output: Number of created files: 374 (reg: 256, dir: 100, link: 12, special: 6)
2024-01-22 19:37:44,237 DEBUG: __main__: Live Output: Number of deleted files: 11,161 (reg: 9,330, dir: 1,184, link: 639, special: 8)
2024-01-22 19:37:44,238 DEBUG: __main__: Live Output: Number of regular files transferred: 1,221
2024-01-22 19:37:44,238 DEBUG: __main__: Live Output: Total file size: 2,431,645,411,137 bytes
2024-01-22 19:37:44,239 DEBUG: __main__: Live Output: Total transferred file size: 2,486,858,133 bytes
2024-01-22 19:37:44,239 DEBUG: __main__: Live Output: Literal data: 800,458,210 bytes
2024-01-22 19:37:44,240 DEBUG: __main__: Live Output: Matched data: 1,686,399,923 bytes
2024-01-22 19:37:44,240 DEBUG: __main__: Live Output: File list size: 32,320,940
2024-01-22 19:37:44,240 DEBUG: __main__: Live Output: File list generation time: 0.001 seconds
2024-01-22 19:37:44,240 DEBUG: __main__: Live Output: File list transfer time: 0.000 seconds
2024-01-22 19:37:44,241 DEBUG: __main__: Live Output: Total bytes sent: 1,658,439
2024-01-22 19:37:44,241 DEBUG: __main__: Live Output: Total bytes received: 861,065,792
2024-01-22 19:37:44,241 DEBUG: __main__: Live Output: 
2024-01-22 19:37:44,242 DEBUG: __main__: Live Output: sent 1,658,439 bytes  received 861,065,792 bytes  400,614.92 bytes/sec
2024-01-22 19:37:44,242 DEBUG: __main__: Live Output: total size is 2,431,645,411,137  speedup is 2,818.57
2024-01-22 19:37:44,320 INFO: __main__: Backup finished.
2024-01-22 19:37:44,320 DEBUG: __main__: Backup output task finished.
2024-01-22 19:37:44,320 ERROR: __main__: Fehlerausgabe: rsync: [sender] read errors mapping "/hdd0/nextcloud_old/martha/files/Bilder/2021_04_23_HedwigOmaZuBesuch/DSC_8486.JPG" (in backup_data_source): Input/output error (5)
rsync: [sender] read errors mapping "/hdd0/nextcloud_old/martha/files/Bilder/2021_04_23_HedwigOmaZuBesuch/DSC_8486.JPG" (in backup_data_source): Input/output error (5)
ERROR: hdd0/nextcloud_old/martha/files/Bilder/2021_04_23_HedwigOmaZuBesuch/DSC_8486.JPG failed verification -- update discarded.
rsync: [sender] read errors mapping "/hdd0/share/MundM/Bilder/2020/2020_10_03-04_Annas_erster_Geburtstag/DSCN5181.JPG" (in backup_data_source): Input/output error (5)
rsync: [sender] read errors mapping "/hdd0/share/MundM/Bilder/2020/2020_10_03-04_Annas_erster_Geburtstag/DSCN5181.JPG" (in backup_data_source): Input/output error (5)
ERROR: hdd0/share/MundM/Bilder/2020/2020_10_03-04_Annas_erster_Geburtstag/DSCN5181.JPG failed verification -- update discarded.
rsync: [sender] readlink_stat("/hdd0/share/MundM/Bilder/2021/2021_04_04_Ostern/20210404_091059.jpg" (in backup_data_source)) failed: Bad message (74)
rsync: [sender] readlink_stat("/hdd0/share/MundM/Bilder/2021/2021_04_04_Ostern/20210404_091049.jpg" (in backup_data_source)) failed: Bad message (74)
rsync: [sender] readlink_stat("/hdd0/share/MundM/Bilder/2021/2021_04_04_Ostern/20210404_090929.jpg" (in backup_data_source)) failed: Bad message (74)
rsync: [sender] readlink_stat("/hdd0/share/MundM/Bilder/2021/2021_04_04_Ostern/20210404_091103.jpg" (in backup_data_source)) failed: Bad message (74)
rsync: [sender] readlink_stat("/hdd0/share/MundM/Bilder/2021/2021_04_04_Ostern/20210404_090858.jpg" (in backup_data_source)) failed: Bad message (74)
rsync: [sender] readlink_stat("/hdd0/share/MundM/Bilder/2021/2021_04_04_Ostern/20210404_090956.jpg" (in backup_data_source)) failed: Bad message (74)
rsync: [sender] readlink_stat("/hdd0/share/MundM/Bilder/2021/2021_04_04_Ostern/20210404_091005.jpg" (in backup_data_source)) failed: Bad message (74)
rsync: [sender] readlink_stat("/hdd0/share/MundM/Bilder/2021/2021_04_04_Ostern/20210404_091046.jpg" (in backup_data_source)) failed: Bad message (74)
rsync: [sender] readlink_stat("/hdd0/share/MundM/Bilder/2021/2021_04_04_Ostern/20210404_090903.jpg" (in backup_data_source)) failed: Bad message (74)
rsync: [sender] readlink_stat("/hdd0/share/MundM/Bilder/2021/2021_04_04_Ostern/20210404_091041.jpg" (in backup_data_source)) failed: Bad message (74)
rsync: [sender] readlink_stat("/hdd0/share/MundM/Bilder/2021/2021_04_04_Ostern/20210404_091051.jpg" (in backup_data_source)) failed: Bad message (74)
rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1865) [generator=3.2.7]

2024-01-22 19:37:44,321 INFO: __main__: Disconnecting Backup HDD
...

Testing a few scenarios

all tests done with laptop

all start with

mkdir testsink
rsync -avh 192.168.0.2::backup_data_source/* testsink/

then

just cancel with Strg+C

^C
rsync error: received SIGINT, SIGTERM, or SIGHUP (code 20) at rsync.c(713) [generator=3.2.7]
rsync error: received SIGINT, SIGTERM, or SIGHUP (code 20) at io.c(518) [receiver=3.2.7]
rsync: [receiver] write error: Broken pipe (32)
rsync error: received SIGINT, SIGTERM, or SIGHUP (code 20) at io.c(1644) [sender=3.2.3]

kill rsync on server

rsync: [receiver] read error: Connection reset by peer (104)
rsync error: error in socket IO (code 10) at io.c(806) [receiver=3.2.7]
rsync: connection unexpectedly closed (507244 bytes received so far) [generator]
rsync error: error in rsync protocol data stream (code 12) at io.c(231) [generator=3.2.7]

pull network cable ... freezes for some time ... a long time ... continues after replugging

More specific

try to sync problematic files

rsync -avh 192.168.0.2::backup_data_source/hdd0/share/MundM/Bilder/2021/2021_04_04_Ostern/* testsink/

just worked flawlessly

sync from usb-stick then pull it

file has vanished: "/media/max/Ubuntu 20.04.4 LTS amd64/preseed/cli.seed"
file has vanished: "/media/max/Ubuntu 20.04.4 LTS amd64/preseed/ltsp.seed"
file has vanished: "/media/max/Ubuntu 20.04.4 LTS amd64/preseed/ubuntu.seed"
WARNING: casper/filesystem.squashfs failed verification -- update discarded (will try again).
casper/filesystem.squashfs
rsync: [sender] read errors mapping "/media/max/Ubuntu 20.04.4 LTS amd64/casper/filesystem.squashfs": Input/output error (5)
ERROR: casper/filesystem.squashfs failed verification -- update discarded.

sent 4,58G bytes  received 17,00K bytes  366,54M bytes/sec
total size is 3,64G  speedup is 0,80
rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1338) [sender=3.2.7]

M-Welsch commented 7 months ago

Analyzing the log from above

2024-01-22 19:07:16,304 DEBUG: __main__: Live Output: skipping non-regular file "dietpi_userdata/docker-data/volumes/backingFsBlockDev"
# some more messages like this, then silence for 30min

2024-01-22 19:37:44,235 DEBUG: __main__: Live Output: 
2024-01-22 19:37:44,236 DEBUG: __main__: Live Output: Number of files: 1,964,660 (reg: 1,657,042, dir: 292,304, link: 15,296, special: 18)
# ... more stats output

2024-01-22 19:37:44,320 INFO: __main__: Backup finished.
2024-01-22 19:37:44,320 DEBUG: __main__: Backup output task finished.
2024-01-22 19:37:44,320 ERROR: __main__: Fehlerausgabe: rsync: [sender] read errors mapping "/hdd0/nextcloud_old/martha/files/Bilder/2021_04_23_HedwigOmaZuBesuch/DSC_8486.JPG" (in backup_data_source): Input/output error (5)
rsync: [sender] read errors mapping "/hdd0/nextcloud_old/martha/files/Bilder/2021_04_23_HedwigOmaZuBesuch/DSC_8486.JPG" (in backup_data_source): Input/output error (5)
ERROR: hdd0/nextcloud_old/martha/files/Bilder/2021_04_23_HedwigOmaZuBesuch/DSC_8486.JPG failed verification -- update discarded.
rsync: [sender] read errors mapping "/hdd0/share/MundM/Bilder/2020/2020_10_03-04_Annas_erster_Geburtstag/DSCN5181.JPG" (in backup_data_source): Input/output error (5)

ERROR: hdd0/share/MundM/Bilder/2020/2020_10_03-04_Annas_erster_Geburtstag/DSCN5181.JPG failed verification -- update discarded.
rsync: [sender] readlink_stat("/hdd0/share/MundM/Bilder/2021/2021_04_04_Ostern/20210404_091059.jpg" (in backup_data_source)) failed: Bad message (74)
# more errors like this

rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1865) [generator=3.2.7]

2024-01-22 19:37:44,321 INFO: __main__: Disconnecting Backup HDD
...

Interesting is:

ERROR appears to the same time rsync finishes
BUT: the ERROR points to a file in /hdd0/nextcloud_old which should be traversed before /hdd0/share/.... Therefore the ERROR might not be the cause for the cancellation after all
stderr seems to be printed after everything else. We should get timestamps for everything here

M-Welsch commented 7 months ago

modified rsync command. Removed the * after the source. (source: https://stackoverflow.com/a/35452860). Tested it beforehand. Operation looks the same

rsync -aH --stats --delete 192.168.0.2::backup_data_source/* /media/BackupHDD/backups/current
# to
rsync -aH --stats --delete 192.168.0.2::backup_data_source/ /media/BackupHDD/backups/current

M-Welsch commented 7 months ago

next logs indicate a successfully performed backup

error logs and "finished" logs are timely separated

Details

next logs:

Jan 22 21:12:11 basehw4sn2 python3[985]: 2024-01-22 21:12:11,672 WARNING: __main__: Live Output: ERROR: hdd0/nextcloud_old/martha/files/Bilder/2021_04_23_HedwigOmaZuBesuch/DSC_8486.JPG failed verification -- update discarded.
Jan 22 21:22:51 basehw4sn2 python3[985]: 2024-01-22 21:22:51,194 WARNING: __main__: Live Output: rsync: [sender] read errors mapping "/hdd0/share/MundM/Bilder/2020/2020_10_03-04_Annas_erster_Geburtstag/DSCN5181.JPG" (in backup_data_source): Input/output error (5)
Jan 22 21:23:22 basehw4sn2 python3[985]: 2024-01-22 21:23:22,803 WARNING: __main__: Live Output: rsync: [sender] read errors mapping "/hdd0/share/MundM/Bilder/2020/2020_10_03-04_Annas_erster_Geburtstag/DSCN5181.JPG" (in backup_data_source): Input/output error (5)
Jan 22 21:23:22 basehw4sn2 python3[985]: 2024-01-22 21:23:22,813 WARNING: __main__: Live Output: ERROR: hdd0/share/MundM/Bilder/2020/2020_10_03-04_Annas_erster_Geburtstag/DSCN5181.JPG failed verification -- update discarded.
Jan 22 21:25:16 basehw4sn2 python3[985]: 2024-01-22 21:25:16,420 DEBUG: __main__: Live Output:
Jan 22 21:25:16 basehw4sn2 python3[985]: 2024-01-22 21:25:16,421 DEBUG: __main__: Live Output: Number of files: 1,964,672 (reg: 1,657,053, dir: 292,305, link: 15,296, special: 18)
Jan 22 21:25:16 basehw4sn2 python3[985]: 2024-01-22 21:25:16,422 DEBUG: __main__: Live Output: Number of created files: 13 (reg: 13)
# ... stats ...

Jan 22 21:25:16 basehw4sn2 python3[985]: 2024-01-22 21:25:16,460 WARNING: __main__: Live Output: rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1865) [generator=3.2.7]
Jan 22 21:25:16 basehw4sn2 python3[985]: 2024-01-22 21:25:16,497 INFO: __main__: Backup finished.

here are the errors (picked out from above)

Jan 22 21:12:11 basehw4sn2 python3[985]: 2024-01-22 21:12:11,672 WARNING: __main__: Live Output: ERROR: hdd0/nextcloud_old/martha/files/Bilder/2021_04_23_HedwigOmaZuBesuch/DSC_8486.JPG failed verification -- update discarded.
...
Jan 22 21:23:22 basehw4sn2 python3[985]: 2024-01-22 21:23:22,813 WARNING: __main__: Live Output: ERROR: hdd0/share/MundM/Bilder/2020/2020_10_03-04_Annas_erster_Geburtstag/DSCN5181.JPG failed verification -- update discarded.
...
Jan 22 21:25:16 basehw4sn2 python3[985]: 2024-01-22 21:25:16,497 INFO: __main__: Backup finished.

between the errors and the finished-log are 2 and 23 minutes. Unlikely that the errors caused rsync to stop. Btw. there are no errors logged on the server side

Random other thing

this line keeps appearing.

ERROR: hdd0/share/MundM/Bilder/2020/2020_10_03-04_Annas_erster_Geburtstag/DSCN5181.JPG failed verification -- update discarded.

the file seems to be corrupt

 rsync 192.168.0.2::backup_data_source/hdd0/share/MundM/Bilder/2020/2020_10_03-04_Annas_erster_Geburtstag/DSCN5181.JPG testsink/
rsync: [sender] read errors mapping "/hdd0/share/MundM/Bilder/2020/2020_10_03-04_Annas_erster_Geburtstag/DSCN5181.JPG" (in backup_data_source): Input/output error (5)
rsync: [sender] read errors mapping "/hdd0/share/MundM/Bilder/2020/2020_10_03-04_Annas_erster_Geburtstag/DSCN5181.JPG" (in backup_data_source): Input/output error (5)
ERROR: DSCN5181.JPG failed verification -- update discarded.
rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1865) [generator=3.2.7]
# no file synchronized over rsync

# and
scp server:/mnt/hdd0/share/MundM/Bilder/2020/2020_10_03-04_Annas_erster_Geburtstag/DSCN5181.JPG .
DSCN5181.JPG                                                                                                                                                                      46% 2000KB 723.7KB/s   00:03 ETAscp: /mnt/hdd0/share/MundM/Bilder/2020/2020_10_03-04_Annas_erster_Geburtstag/DSCN5181.JPG: Input/output error
DSCN5181.JPG                                                                                                                                                                     100% 4337KB   1.5MB/s   00:02  
# transferred over scp and the image is half-intact

M-Welsch / backup-server

[END OF MVP] reallife backup test #31

Description

What happens if we don't do it (aka Why is it important)?

Definition of Ready

Key Tasks

Acceptance Criteria

Testing a few scenarios

More specific

sync from usb-stick then pull it

Details

Random other thing