Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Rsync error 23 #1555

Open
Hizoka76 opened this issue Oct 28, 2023 · 13 comments
Open

Rsync error 23 #1555

Hizoka76 opened this issue Oct 28, 2023 · 13 comments
Assignees
Labels
Discussion decision or consensus needed

Comments

@Hizoka76
Copy link

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
Copy link
Contributor

aryoda commented Oct 28, 2023

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):

backintime/common/snapshots.py

Lines 1245 to 1250 in bda3a0c

# dict of exit codes (as keys) that are treated as INFO only by BiT
# (not as ERROR). The values are message strings for the snapshot log.
rsync_non_error_exit_codes = {
0: _("Success"),
24: _("Partial transfer due to vanished source files (see 'man rsync')")
}

@aryoda aryoda added the Discussion decision or consensus needed label Oct 28, 2023
@aryoda aryoda self-assigned this Oct 28, 2023
@Hizoka76
Copy link
Author

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
Copy link
Contributor

aryoda commented Oct 29, 2023

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
Copy link
Author

Hizoka76 commented Oct 30, 2023

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
Copy link
Contributor

aryoda commented Oct 30, 2023

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
Copy link
Author

Hizoka76 commented Oct 31, 2023

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...

@aryoda aryoda added the Bug label Oct 31, 2023
@Hizoka76
Copy link
Author

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
Copy link
Contributor

aryoda commented Oct 31, 2023

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
Copy link
Contributor

aryoda commented Oct 31, 2023

/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
Copy link
Author

Hizoka76 commented Oct 31, 2023

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 aryoda removed the Bug label Nov 1, 2023
@aryoda
Copy link
Contributor

aryoda commented Nov 1, 2023

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

  1. DONE: Mention exit code 23 in the FAQ + how to diagnose
  2. Add Discord and Mozzila lock files to the standard exclusion list of BiT
  3. Goal of Master issue for "error 23" (rsync returns with exit code 23: Partial transfer due to errors) #1587 now: Check if there is a reliable way to show rsync IO errors as ERROR instead of INFO in the snapshot log

@buhtz
Copy link
Member

buhtz commented Dec 8, 2023

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 added a commit that referenced this issue Dec 27, 2023
FAQ and dev doc: Closes #1166, #1582. Contributes to #1555 and #1587

- Add FAQ entry: Snapshot "WITH ERRORS": [E] 'rsync' ended with exit code 23
- Add FAQ entry: Does BiT support full system backups?
- Add FAQ entry: Does BiT support backups on cloud storage like OneDrive or Google Drive?
- Corrects some other typos in code comments
- Add details about global locking to dev doc of control files usage
@buhtz buhtz added this to the upcoming release (1.4.2) milestone Jan 9, 2024
aryoda added a commit to aryoda/backintime that referenced this issue Jan 26, 2024
* rsync exit code 23 is now in the ignore list
* Add experimental "rsync transfer failures" filter to snapshot log view
* Exclude 'SingletonLock' and 'SingletonCookie' (Discord) and 'lock' (Mozilla Firefox) files by default (part of bit-team#1555)
aryoda added a commit that referenced this issue Jan 29, 2024
…napshot log filter (#1621)

* Work around for rsync exit code 23: Is no longer an error by adding it to the rsync exit code ignore list (#1587)
* Add experimental "rsync transfer failures" filter to snapshot log view
* Add links to rsync source code for rsync transfer failure filter
* Exclude 'SingletonLock' and 'SingletonCookie' (Discord) and 'lock' (Mozilla Firefox) files by default (part of #1555)
* Travis CI config file adjustments since coverage does fail with absolute path to Python for unknown reason (only relative path works)
* CI: Remove sudo because travis says so ("no effect anymore")

---------

Co-authored-by: aryoda <11374410+aryoda@users.noreply.github.com>
Co-authored-by: Christian Buhtz <c.buhtz@posteo.jp>
@aryoda
Copy link
Contributor

aryoda commented Feb 1, 2024

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:
    image

@buhtz buhtz added this to the 3rd release from now milestone Oct 18, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Discussion decision or consensus needed
Projects
None yet
Development

No branches or pull requests

3 participants