in some situations rsync stops and after some time error unexplained error (code 255) at io.c(226)

[bacarrdy]

Hello,

We have a lot of servers what we are backing up via backuppc and now we have installed new backuppc system on centos 8 and noticed that on only few servers we have issues when backup stops and freezes and then gives error:

rsync_bpc: connection unexpectedly closed (42360 bytes received so far) [receiver]
Done: 0 errors, 0 filesExist, 0 sizeExist, 0 sizeExistComp, 0 filesTotal, 0 sizeTotal, 0 filesNew, 0 sizeNew, 0 sizeNewComp, 6735 inode
rsync error: error in rsync protocol data stream (code 12) at io.c(226) [receiver=3.1.3.0]
[receiver] _exit_cleanup(code=12, file=io.c, line=226): about to call exit(12)
rsync_bpc: connection unexpectedly closed (51093 bytes received so far) [generator]
DoneGen: 0 errors, 0 filesExist, 0 sizeExist, 0 sizeExistComp, 355 filesTotal, 15231605 sizeTotal, 0 filesNew, 0 sizeNew, 0 sizeNewComp, 6734 inode
rsync error: unexplained error (code 255) at io.c(226) [generator=3.1.3.0]
[generator] _exit_cleanup(code=12, file=io.c, line=226): about to call exit(255)

So i have started backup from cli with command /usr/share/BackupPC/bin/BackupPC_dump -f -vvv target_host and collected rsync_bpc at what rsync_bpc stucked:

/usr/bin/rsync_bpc -vvv --bpc-top-dir /data/BackupPC/ --bpc-host-name target_host --bpc-share-name /var/lib/mysql --bpc-bkup-num 1 --bpc-bkup-comp 3 --bpc-bkup-prevnum -1 --bpc-bkup-prevcomp -1 --bpc-bkup-inode0 6734 --bpc-log-level 1 --bpc-attrib-new -e /usr/bin/ssh\ -p\ 11111\ -q\ -x\ -l\ root --rsync-path=/usr/bin/rsync --super --recursive --protect-args --numeric-ids --perms --owner --group -D --times --links --hard-links --delete --delete-excluded --partial --log-format=log:\ %o\ %i\ %B\ %8U,%8G\ %9l\ %f%L --stats --checksum --timeout=72000 target_host:/var/lib/mysql/ /

And then started rcync process with this command and rsync process stucked at (Please keep in mind that this is not first directory for what backuppc was runing on same server, but last one and as i noticed backuppc for each directory generate rsync command. Also x@0024waits_global_by_latency.frm,374 is the last file from folder):

recv_generator(sys/x@0024wait_classes_global_by_avg_latency.frm,370)
recv_generator(sys/x@0024wait_classes_global_by_latency.frm,371)
recv_generator(sys/x@0024waits_by_host_by_latency.frm,372)
recv_generator(sys/x@0024waits_by_user_by_latency.frm,373)
recv_generator(sys/x@0024waits_global_by_latency.frm,374)
generate_files phase=1
rsync_bpc: connection unexpectedly closed (42360 bytes received so far) [receiver]
Done: 0 errors, 0 filesExist, 0 sizeExist, 0 sizeExistComp, 0 filesTotal, 0 sizeTotal, 0 filesNew, 0 sizeNew, 0 sizeNewComp, 6735 inode
rsync error: error in rsync protocol data stream (code 12) at io.c(226) [receiver=3.1.3.0]
[receiver] _exit_cleanup(code=12, file=io.c, line=226): about to call exit(12)
rsync_bpc: connection unexpectedly closed (51093 bytes received so far) [generator]
DoneGen: 0 errors, 0 filesExist, 0 sizeExist, 0 sizeExistComp, 355 filesTotal, 15231605 sizeTotal, 0 filesNew, 0 sizeNew, 0 sizeNewComp, 6734 inode
rsync error: unexplained error (code 255) at io.c(226) [generator=3.1.3.0]
[generator] _exit_cleanup(code=12, file=io.c, line=226): about to call exit(255)

Second server what has same issue:

bash-4.4$ /usr/share/BackupPC/bin/BackupPC_dump -f -vvv target2_host
Backup type: type = full, needs_full = 1, needs_incr = 1, lastFullTime = 0, opts{f} = 1, opts{i} = , opts{F} =
cmdSystemOrEval: about to system /bin/echo -c 1 target2_host
cmdSystemOrEval: about to system /bin/echo -c 1 target2_host
CheckHostAlive: can't extract round-trip time (not fatal)
CheckHostAlive: ran '/bin/echo -c 1 target2_host'; returning 0
XferLOG file /data/BackupPC//pc/target2_host/XferLOG.0.z created 2021-02-17 15:18:18
Backup prep: type = full, case = 1, inPlace = 1, doDuplicate = 0, newBkupNum = 0, newBkupIdx = 0, lastBkupNum = , lastBkupIdx = (FillCycle = 0, noFillCnt = )
bpc_progress_state backup share "/var/lib"
Running: /usr/bin/rsync_bpc --bpc-top-dir /data/BackupPC/ --bpc-host-name target2_host --bpc-share-name /var/lib --bpc-bkup-num 0 --bpc-bkup-comp 3 --bpc-bkup-prevnum -1 --bpc-bkup-prevcomp -1 --bpc-bkup-inode0 2 --bpc-log-level 1 --bpc-attrib-new -e /usr/bin/ssh\ -p\ 11111\ -q\ -x\ -l\ root --rsync-path=/usr/bin/rsync --super --recursive --protect-args --numeric-ids --perms --owner --group -D --times --links --hard-links --delete --delete-excluded --partial --log-format=log:\ %o\ %i\ %B\ %8U,%8G\ %9l\ %f%L --stats --checksum --timeout=72000 --exclude=/proc --exclude=/tmp --exclude=/var/spool/exim --exclude=/var/spool/pmta --exclude=/var/spool/postfix --exclude=*.log --exclude=*.log.* --exclude=*.pid --exclude=sess_* --exclude=*.avi --exclude=*.deb --exclude=*.dmp target2_host:/var/lib/ /
full backup started for directory /var/lib
started full dump, share=/var/lib
Xfer PIDs are now 20910
xferPids 20910
This is the rsync child about to exec /usr/bin/rsync_bpc
cmdExecOrEval: about to exec /usr/bin/rsync_bpc --bpc-top-dir /data/BackupPC/ --bpc-host-name target2+host --bpc-share-name /var/lib --bpc-bkup-num 0 --bpc-bkup-comp 3 --bpc-bkup-prevnum -1 --bpc-bkup-prevcomp -1 --bpc-bkup-inode0 2 --bpc-log-level 1 --bpc-attrib-new -e /usr/bin/ssh\ -p\ 11111\ -q\ -x\ -l\ root --rsync-path=/usr/bin/rsync --super --recursive --protect-args --numeric-ids --perms --owner --group -D --times --links --hard-links --delete --delete-excluded --partial --log-format=log:\ %o\ %i\ %B\ %8U,%8G\ %9l\ %f%L --stats --checksum --timeout=72000 --exclude=/proc --exclude=/tmp --exclude=/var/spool/exim --exclude=/var/spool/pmta --exclude=/var/spool/postfix --exclude=*.log --exclude=*.log.* --exclude=*.pid --exclude=sess_* --exclude=*.avi --exclude=*.deb --exclude=*.dmp target2_host:/var/lib/ /
Xfer PIDs are now 20910,20913
xferPids 20910,20913
xferPids 20910,20913
new recv cd+++++++++ rwx------ 0, 0 4096 .
new recv cd+++++++++ rwxr-xr-x 0, 0 4096 1052039
bpc_progress_fileCnt 1
bpc_progress_fileCnt 21
bpc_progress_fileCnt 41
bpc_progress_fileCnt 61
bpc_progress_fileCnt 81
bpc_progress_fileCnt 101
bpc_progress_fileCnt 121
bpc_progress_fileCnt 141
same recv >f..tp..... rw-r--r-- 0, 0 0 1052039/fastboot
rsync_bpc: connection unexpectedly closed (38533 bytes received so far) [receiver]
Done: 0 errors, 0 filesExist, 0 sizeExist, 0 sizeExistComp, 0 filesTotal, 0 sizeTotal, 0 filesNew, 0 sizeNew, 0 sizeNewComp, 7 inode
rsync error: error in rsync protocol data stream (code 12) at io.c(226) [receiver=3.1.3.0]
rsync_bpc: connection unexpectedly closed (54016 bytes received so far) [generator]
DoneGen: 0 errors, 159 filesExist, 3935 sizeExist, 4941 sizeExistComp, 160 filesTotal, 3935 sizeTotal, 0 filesNew, 0 sizeNew, 0 sizeNewComp, 2146 inode
rsync error: unexplained error (code 255) at io.c(226) [generator=3.1.3.0]
rsync_bpc exited with fatal status 255 (65280) (rsync error: unexplained error (code 255) at io.c(226) [generator=3.1.3.0])
Xfer PIDs are now
xferPids
Got fatal error during xfer (rsync error: unexplained error (code 255) at io.c(226) [generator=3.1.3.0])
cmdSystemOrEval: about to system /bin/echo -c 1 target2_host
cmdSystemOrEval: about to system /bin/echo -c 1 target2_host
CheckHostAlive: can't extract round-trip time (not fatal)
CheckHostAlive: ran '/bin/echo -c 1 target2_host'; returning 0
Backup aborted (rsync error: unexplained error (code 255) at io.c(226) [generator=3.1.3.0])
bpc_progress_state fail cleanup
BackupFailCleanup: nFilesTotal = 160, type = full, BackupCase = 1, inPlace = 1, lastBkupNum =
Keeping non-empty backup #0 (/data/BackupPC//pc/target2_host/0)
bpc_progress_state fsck
Running BackupPC_refCountUpdate -h target2_host -f on target2_host
cmdSystemOrEval: about to system /usr/share/BackupPC/bin/BackupPC_refCountUpdate -h target2_host -f
Xfer PIDs are now 20922
xferPids 20922
bpc_progress_state refCnt #0
BackupPC_refCountUpdate: target2_host #0 inodeLast set to 2132 (was 1)
bpc_progress_state cntUpdate #0
bpc_progress_state rename #0
bpc_progress_state sumUpdate
bpc_progress_fileCnt 0/128
bpc_progress_fileCnt 8/128
bpc_progress_fileCnt 16/128
bpc_progress_fileCnt 24/128
bpc_progress_fileCnt 32/128
bpc_progress_fileCnt 40/128
bpc_progress_fileCnt 48/128
bpc_progress_fileCnt 56/128
bpc_progress_fileCnt 64/128
bpc_progress_fileCnt 72/128
bpc_progress_fileCnt 80/128
bpc_progress_fileCnt 88/128
bpc_progress_fileCnt 96/128
bpc_progress_fileCnt 104/128
bpc_progress_fileCnt 112/128
bpc_progress_fileCnt 120/128
bpc_progress_state rename total
BackupPC_refCountUpdate: host target2_host got 0 errors (took 0 secs)
Xfer PIDs are now
xferPids
Finished BackupPC_refCountUpdate (running time: 0 sec)
Xfer PIDs are now
xferPids
dump failed: rsync error: unexplained error (code 255) at io.c(226) [generator=3.1.3.0]

if need to collect any additional data please tell me

[bacarrdy]

[root@backuppc ~]# yum list installed rsync-bpc
Installed Packages
rsync-bpc.x86_64 3.1.3.0-1.el8 @epel
[root@backuppc ~]# yum list installed rsync
Installed Packages
rsync.x86_64 3.1.3-12.el8 @anaconda
[root@backuppc ~]#

[craigbarratt]

Thanks for providing the output from BackupPC_dump -f -v target2_host. It fails quite quickly.

BackupPC_dump only takes a single -v option, so repeating it don't increase the log level. Please re-run manually with two changes (but still keep -v on BackupPC_dump):

• add '-vvv' to $Conf{RsyncArgs}
• increase $Conf{XferLogLevel} to 7

By the way, the default $Conf{RsyncSshArgs} has added -o ServerAliveInterval=60 so you might try adding that too. The git default is now:

$Conf{RsyncSshArgs} = ['-e', '$sshPath -l root -o ServerAliveInterval=60'];

[bacarrdy]

Hello,

Sorry for delay. I have deleted all backups of backup target (it starts backups but not finish) and then started again with required by you opinions. As i can see it looks that it tryes to make backup of one of folders, but doesnt start second.

Log attached
log.txt

if you will need log from another target then just tell me.

[nicolasgoudard]

HI ! UP. I have the same problem, I put the same parameters (ServerAliveInterval=60 and ServerAliveCountMax=0)

Backup aborted (rsync error: unexplained error (code 255) at io.c(226) [generator=3.1.3.0])

I don't know how to do.

[nicolasgoudard]

UP again . I found the reason . I put a bad character in the .ssh/config file on the backuppc server . But I don't understand why the server needs the file, indeed I put "-o " options in the ssh command in the backuppc configuration , so I don't understand why it would need this file ?

[TheNetworkIsDown]

We're facing the same symptoms here.
I am now trying to implement verbose output from #20 (comment)
Too bad that each log line does not necessarily include an exact timestamp what happened when, otherwise it would be easier troubleshooting on network side etc as well.
BTW we're also facing #28 regularly.
All of it happening on a host with tens of millions of files.

[TheNetworkIsDown]

The SSH client (on the backuppc server) is just disappearing as it seems.
And then it looks like this:

42de9328cf40862dec68537787c95022 1
1403fad62d5cef9cf2a877be379c31ac 1
5933c24cba1cadc8b80353e47e2665b5 1
DoneGen: 0 errors, 0 filesExist, 0 sizeExist, 0 sizeExistComp, 22482011 filesTotal, 122747042777 sizeTotal, 0 filesNew, 0 sizeNew, 0 sizeNewComp, 120668498 inode
Parsing done: nFilesTotal = 22482011
rsync error: unexplained error (code 255) at io.c(226) [generator=3.1.3.0]
[generator] _exit_cleanup(code=12, file=io.c, line=226): about to call exit(255)
rsync_bpc exited with fatal status 255 (65280) (rsync error: unexplained error (code 255) at io.c(226) [generator=3.1.3.0])
Xfer PIDs are now
Executing DumpPostUserCmd:..

SSH server (on the client) is reporting the following more or less at the same time

2024-08-10T01:21:30.125447+02:00 host sshd[23918]: Read error from remote host 1.2.3.118: Connection timed out
2024-08-10T01:21:30.125710+02:00 host sshd[23918]: debug1: do_cleanup

RsyncClientPath: nice -n 19 ionice -c2 -n7 sudo /usr/bin/rsync
RsyncSshArgs: $sshPath -l backuppc -o ServerAliveInterval=60 -v

I'm trying to increase this to "-vvv" then...

[GWHAYWOOD]

If this issue is still unresolved, please let me know.

A new version of rsync-bpc is in testing. It is based on rsync-3.4.1 and it might be worth giving it a spin to see if it changes anything about this issue.

[GWHAYWOOD]

Closing, no response.