Rsync error 23 - Githubissues

Hizoka76 commented 1 year ago

Hi,

since the 1.4.1-1 update, all my backups end up with error 23.

The backup crashes very quickly and never on the same files.

I was supposedly in version 1.3.3-3 before the update via the ppa https://launchpad.net/~bit-team/+archive/ubuntu/stable.

I have backups on an external hard disk that work.

I tried to run the command backintime backup :

Back In Time
Version: 1.4.1-1

Back In Time comes with ABSOLUTELY NO WARRANTY.
This is free software, and you are welcome to redistribute it
under certain conditions; type `backintime --license' for details.

INFO: Lock
INFO: Take a new snapshot. Profile: 1 Profil principal
INFO: Call rsync to take the snapshot
WARNING: Command "rsync --recursive --times --devices --specials --hard-links --human-readable -s --copy-links --acls --perms --executability --group --owner --info=progress2 --no-inc-recursive --delete --delete-excluded -v -i --out-format=BACKINTIME: %i %n%L --link-dest=../../20231028-125232-168/backup --chmod=Du+wx --exclude=/home/hizoka/Sauvegarde --exclude=/home/hizoka/.local/share/backintime --exclude=.local/share/backintime/mnt --include=/home/hizoka/Autres/ --include=/home/hizoka/ --include=/home/ --include=/home/hizoka/.bogofilter/ --include=/home/hizoka/.config/ --include=/home/hizoka/.kde/ --include=/home/hizoka/.local/ --include=/home/hizoka/.ssh/ --include=/home/hizoka/.xnviewmp/ --include=/home/hizoka/Scripts_et_logiciels/ --include=/home/hizoka/Multimedia/Images/ --include=/home/hizoka/Multimedia/ --include=/home/hizoka/Multimedia/Musiques/ --include=/home/hizoka/.gnupg/ --include=/home/hizoka/.password-store/ --include=/home/hizoka/.skrooge/ --include=/home/hizoka/Multimedia/Scans/ --include=/home/hizoka/.mozilla/ --include=/home/hizoka/.thunderbird/ --include=/home/hizoka/.epsonscan2/ --exclude=.gvfs --exclude=.cache* --exclude=[Cc]ache* --exclude=.thumbnails* --exclude=[Tt]rash* --exclude=*.backup* --exclude=*~ --exclude=.dropbox* --exclude=/home/hizoka/.kde/share/apps/RecentDocuments --exclude=/home/hizoka/.local/share/Steam --exclude=/home/hizoka/.local/share/Trash --exclude=/home/hizoka/.local/share/RecentDocuments --exclude=/home/hizoka/Download --exclude=/home/hizoka/Scripts_et_logiciels/SousHome/log --exclude=/home/hizoka/.config/falkon --exclude=/home/hizoka/Scripts_et_logiciels/SousHome/config/falkon --exclude=/home/hizoka/Scripts_et_logiciels/SousHome/local/share/RecentDocuments --exclude=/home/hizoka/Scripts_et_logiciels/log --exclude=/home/hizoka/.local/share/baloo --exclude=/home/hizoka/Scripts_et_logiciels/iso/TrueCrypt --exclude=/home/hizoka/Scripts_et_logiciels/iso/VirtualBox --exclude=/home/hizoka/Scripts_et_logiciels/logiciels/Jeux/Steam --include=/home/hizoka/Autres/** --include=/home/hizoka/.bogofilter/** --include=/home/hizoka/.config/** --include=/home/hizoka/.kde/** --include=/home/hizoka/.local/** --include=/home/hizoka/.ssh/** --include=/home/hizoka/.xnviewmp/** --include=/home/hizoka/Scripts_et_logiciels/** --include=/home/hizoka/Multimedia/Images/** --include=/home/hizoka/Multimedia/Musiques/** --include=/home/hizoka/.gnupg/** --include=/home/hizoka/.password-store/** --include=/home/hizoka/.skrooge/** --include=/home/hizoka/Multimedia/Scans/** --include=/home/hizoka/.mozilla/** --include=/home/hizoka/.thunderbird/** --include=/home/hizoka/.epsonscan2/** --exclude=* / /home/hizoka/Sauvegarde/backintime/HizoNeon/hizoka/SavePrincipale/new_snapshot/backup" returns 23
notify-send Back In Time (hizoka) : Profil principal 'rsync' s'est terminé avec le code retour 23: Voir 'man rsync' pour plus de détails
INFO: Save config file
INFO: Save permissions
INFO: Create info file
ERROR: New snapshot taken but errors detected
INFO: Unlock

If I launch this same command into /home/hizoka/Sauvegarde/backintime/HizoNeon/hizoka/SavePrincipale/test that's work.

I have 1.5TB free on this disk.

Any Idea ?

Thank you

aryoda commented 1 year ago

notify-send Back In Time (hizoka) : Profil principal 'rsync' s'est terminé avec le code retour 23: Voir 'man rsync' pour plus de détails

rsync is returning the exit code 23 which means:

23 - Partial transfer due to error

Since BiT Version 1.4.0 (2023-09-14) the rsync exit code is evaluated for warnings and errors (see #489), before that the exit code was ignored (and the snapshot could have been incomplete without knowing it - in the worst case).

Could you please check the snapshot log for more details about the reason for the partial file transfer and show it here? You can find this in the snapshot log GUI of the profile by changing the filter to "All" (or "Errors" or "Errors+Changes") to find the failed files.

I can then decide if we treat exit code 23 like an error or perhaps only as ~warning~ INFO...

Edit: Exit code 24 is similar and already treated as INFO only (but for a well-known reason):

https://github.com/bit-team/backintime/blob/bda3a0cab618933bde3395182210346830a54863/common/snapshots.py#L1245-L1250

Hizoka76 commented 1 year ago

No information in the log :

...
[C] >f.st...... home/hizoka/Scripts_et_logiciels/scripts/Gladys/PCTemp.log
[E] 'rsync' s'est terminé avec le code retour 23: Voir 'man rsync' pour plus de details

Just the error 23.

aryoda commented 1 year ago

OK, I have browsed the rsync source code a little bit and it looks like exit code 23 may also be caused when "only" file attributes do differ.

Which file systems are you using on the source and target side (and which mount options - use mount to find out the actual mount options)?

Edit:

No information in the log :

Could you please double check the snapshot log in the GUI with the "All" filter to find any hint on a non-copied file or folder? The log is very long and may not use the word "error" but "failed" or similar to indicate the missing file so it is best to scroll through the list manually...

Also: You could add "--stats -P" in the profile (Expert Options > Paste additional options to rsync) to get more details when re-running the snapshot.

Edit 2: Internal note @aryoda : the used expert options "Preserve ACL" (--acls) and "Copy links (dereference symbolic links)" (--copy-links) could cause this too. How to diagnose this?

Hizoka76 commented 1 year ago

Which file systems are you using on the source and target side (and which mount options - use mount to find out the actual mount options)? => ext4 to ext4 => No option, fstab : ext4 defaults 0 2

Could you please double check the snapshot log in the GUI with the "All" filter to find any hint on a non-copied file or folder? The log is very long and may not use the word "error" but "failed" or similar to indicate the missing file so it is best to scroll through the list manually... => No errors or warnings, there aren't many lines unlike before when there were several thousand...

Thanks

EDIT: After add --stats -P and launch the rsync command:

Number of files: 422.721 (reg: 377.475, dir: 45.243, special: 3)
Number of created files: 1.279 (reg: 1.218, dir: 61)
Number of deleted files: 0
Number of regular files transferred: 2.770
Total file size: 1,60T bytes
Total transferred file size: 23,73G bytes
Literal data: 23,73G bytes
Matched data: 0 bytes
File list size: 14,09M
File list generation time: 4,735 seconds
File list transfer time: 0,000 seconds
Total bytes sent: 23,75G
Total bytes received: 57,40K

sent 23,75G bytes  received 57,40K bytes  56,35M bytes/sec
total size is 1,60T  speedup is 67,44
rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1338) [sender=3.2.7]

It says "see previous errors" but I don't see another errors...

I have deleted all saves with errors and relaunch a new save, it seems that everything is OK, it has saved a few gigs. But always this error 23.

aryoda commented 1 year ago

The mount seems OK and more surprisingly the source and target are on the same mount so that I would not expect permission problems.

Could you please uncheck the expert options "Preserve ACL" (--acls) in the GUI and test it again.

I suspect a file or folder with root or special execution rights to be inaccessible (even though rsync does not show which file it is).

If error 23 still occurs then please try to also uncheck the "Copy links (dereference symbolic links)" (--copy-links) in the expert options and create another snapshot.

I want to find out which option provokes error 23 and ask for guidance at the rsync mailing list.

BTW: BiT < v.1.4.0 silently ignores the error so you did not even know that some files are not backed-up but BiT should show you a warning then instead of an error IMHO (but I still need to understand the underlying reason for this).

PS: When I create a file with root-only access in the backup source folder (sudo touch root_only.txt; sudo chmod 600 root_only.txt) and use the "Preserve ACL" expert option may snapshot fails with this output (so I do see the file that triggers exit code 23):

[E] Error: rsync: [sender] send_files failed to open "/home/<user>/Documents/root_only_file.txt": Permission denied (13)
[E] 'rsync' ended with exit code 23: See 'man rsync' for more details

Hizoka76 commented 1 year ago

The mount seems OK and more surprisingly the source and target are on the same mount so that I would not expect permission problems. If error 23 still occurs then please try to also uncheck the "Copy links (dereference symbolic links)" (--copy-links) in the expert options and create another snapshot.

I have many disks with many symbolic links fstab:

# /
UUID=6a04d4ec-0881-4aa8-aefd-448ab011ee41       /                                           ext4    errors=remount-ro,noatime 0 1

# /dev/nvme0n1p7 => /media/Partage
UUID=185ef010-c5bf-485b-adf6-9b52cbf4e829       /media/Partage                              ext4    defaults       0    2

# /dev/sdb2 => /media/SeizeTera (16To)
UUID=6596a59c-868c-4a92-9fb6-95b066dfee6f       /media/SeizeTera                         ext4    defaults       0    2

# /media/QuatreTera (4To)
UUID=84c1634a-6931-4943-885f-841f459bc19a       /home/hizoka/Sauvegarde                           ext4    defaults       0    2

My home:

ls -l /home/hizoka
lrwxrwxrwx 1 hizoka hizoka   23 sept.  7 00:22 Autres -> /media/SeizeTera/Autres
lrwxrwxrwx 1 hizoka hizoka   24 sept.  7 12:44 Download -> /media/Partage/Download/
drwxrwxr-x 3 hizoka hizoka 4096 sept.  7 20:04 Multimedia
drwxr-xr-x 6 hizoka hizoka 4096 oct.  30 10:20 Sauvegarde
lrwxrwxrwx 1 hizoka hizoka   38 sept.  7 12:09 Scripts_et_logiciels -> /media/SeizeTera/Scripts_et_logiciels/

ls -l /home/hizoka/Multimedia/
total 4
lrwxrwxrwx 1 hizoka hizoka   23 sept.  7 00:15 Images -> /media/SeizeTera/Images
lrwxrwxrwx 1 hizoka hizoka   25 sept.  7 00:16 Musiques -> /media/SeizeTera/Musiques
lrwxrwxrwx 1 hizoka hizoka   22 sept.  7 00:17 Scans -> /media/SeizeTera/Scans
drwxrwxr-x 2 hizoka hizoka 4096 sept. 22 18:41 Videos

Without --copy-links option, no error but I need this option.

I suspect a file or folder with root or special execution rights to be inaccessible (even though rsync does not show which file it is). Could you please uncheck the expert options "Preserve ACL" (--acls) in the GUI and test it again.

I tried, no change, same error.

BTW: BiT < v.1.4.0 silently ignores the error so you did not even know that some files are not backed-up but BiT should show you a warning then instead of an error IMHO (but I still need to understand the underlying reason for this).

You right, I see same error in old saves

PS: When I create a file with root-only access in the backup source folder (sudo touch root_only.txt; sudo chmod 600 root_only.txt) and use the "Preserve ACL" expert option may snapshot fails with this output (so I do see the file that triggers exit code 23):

Yes, that true (I tried) but not in my case...

Hizoka76 commented 1 year ago

I understand, these are the folders: /home/hizoka/.conf/discord /home/hizoka/.mozzila /home/hizoka/.thunderbird

without them, no more error messages.

Thank you !

aryoda commented 1 year ago

Great to hear you found the reason for exit code 23! It looks like there are some files in use...

How did you find out which files/folders are causing this?

And do ACLs still make a difference?

Perhaps I can improve the logging to make reason for this problem more obvious...

PS: I thought about running the logged rsync command with all the args again (stand-alone in the terminal) to probably see more error output (but this requires to create the new_snapshot/backup folder first I think...

aryoda commented 1 year ago

/home/hizoka/.mozzila

Using my own .mozzila folder in a backup I can reproduce exit code 23 now!

The reason for the problem is shown only as info (without any further hint by rsync about which files or folders cause this):

[I] Take snapshot (rsync: IO error encountered -- skipping file deletion)

THX a lot for testing and your feed-back here!

Edit: I could find an info in the snapshot log that could indicate the file causing the problem:

[I] Take snapshot (rsync: symlink has no referent: "/home/<user>/.mozilla/firefox/upi0vaa1.default/lock")

This lock file is a strange symbolic link to localhost (inodes can point to mounted network devices):

~/.mozilla/firefox/o6okz30c.default-release - broken  > stat lock
  File: lock -> 127.0.1.1:+2329
  Size: 15          Blocks: 0          IO Block: 4096   symbolic link
Device: 10305h/66309d   Inode: 8913038     Links: 1
Access: (0777/lrwxrwxrwx)  Uid: ( 1000/ <user>)   Gid: ( 1000/ <group>)
Access: 2023-10-31 13:17:43.467716547 +0100
Modify: 2022-08-05 00:54:42.331254842 +0200
Change: 2022-08-05 00:54:42.331254842 +0200
 Birth: 2022-08-05 00:54:42.331254842 +0200

If I add this lock file (or generally all files named lock) to the exclusion list in BiT it works without exit code 23.

Hizoka76 commented 1 year ago

How did you find out which files/folders are causing this?

I made many attempts to launch rsync by deleting includes one by one

And do ACLs still make a difference?

No.

If I add this lock file (or generally all files named lock) to the exclusion list in BiT it works without exit code 23.

Yes ! I confirm :)

For Discord: --exclude=SingletonLock --exclude=SingletonCookie

aryoda commented 1 year ago

I would like to keep this issue open until I have fixed the following TODOs:

DONE: Mention exit code 23 in the FAQ + how to diagnose
Add Discord and Mozzila lock files to the standard exclusion list of BiT
Goal of #1587 now: Check if there is a reliable way to show rsync IO errors as ERROR instead of INFO in the snapshot log

buhtz commented 11 months ago

I am not into details here. I discovered three tests where the 23-warning appears in the verbose output. The tests them selfs are passing. Is this expected or points it to problem?

$ pytest -vs test/test_restore.py::TestRestoreSSH::test_restore_file_with_spaces
======================================================================================= test session starts =======================================================================================platform linux -- Python 3.11.2, pytest-7.4.3, pluggy-1.0.0+repack -- /usr/bin/python3
cachedir: .pytest_cache
rootdir: /home/user/mluCloud/my.work/bit/backintime/common
plugins: pyfakefs-5.2.4, anyio-4.0.0
collected 1 item

test/test_restore.py::TestRestoreSSH::test_restore_file_with_spaces INFO: mount ssh: user@localhost:/tmp/tmpta81s26n/foo on /tmp/tmpr2z9cdq1/.local/share/backintime/mnt/5387DBB/mountpoint
INFO: Restore: /tmp/tmpqmqmwrqm/file with spaces to:
WARNING: Command "rsync --recursive --times --devices --specials --hard-links --human-readable -s --links --perms --executability --group --owner --info=progress2 --no-inc-recursive --rsh=ssh -o ServerAliveInterval=240 -o LogLevel=Error -o IdentityFile=/home/user/.ssh/id_rsa -p 22 -R -v --backup --suffix=.backup.20231208 user@localhost:/tmp/tmpta81s26n/foo/backintime/test-host/test-user/1/20151219-010324-123/backup/./tmp/tmpqmqmwrqm/file with spaces /" returns 23 | receiving file list ... done
rsync: [generator] chgrp "/tmp" failed: Operation not permitted (1)
tmp/
tmp/tmpqmqmwrqm/
tmp/tmpqmqmwrqm/file with spaces
              4 100%    3,91kB/s    0:00:00 (xfr#1, to-chk=0/3)

sent 49 bytes  received 183 bytes  154,67 bytes/sec
total size is 4  speedup is 0,02
rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1865) [generator=3.2.7]
INFO: Restore permissions
INFO: unmount ssh: user@localhost:/tmp/tmpta81s26n/foo from /tmp/tmpr2z9cdq1/.local/share/backintime/mnt/5387DBB/mountpoint
PASSEDClearing the cache

======================================================================================== 1 passed in 3.12s ========================================================================================

The other two tests seem to test error cases. So it might be OK that a 23 warning is raised?

test/test_takeSnapshot.py::TestTakeSnapshotSSH::test_takeSnapshot_error
test/test_takeSnapshot.py::TestTakeSnapshotSSH::test_takeSnapshot_error_without_continue

aryoda commented 9 months ago

FYI: The new BiT release v1.4.3 does

reintroduce handling rsync exit code 23 as info only (no longer an error when taking a snapshot)
has an experimental filter now to make finding resync transfer errors easier (even if the are "hidden" as [I]nfo in length snapshot logs:

bit-team / backintime

Rsync error 23 #1555