On 01/19/2017 1:28 PM, Les Mikesell wrote:
On Thu, Jan 19, 2017 at 2:25 PM, John Spitzer <johned9...@comcast.net> wrote:
The most likely suspect is that rsync timeout shown in the log snippet
you posted. But you didn't provide any details about why or how your
rsync had timeouts enabled.
That rsync timeout is being set 'under the hood'. I can't tell from the
logs I've captured already if it's set by BackupPC or the NAS or if the
timeout is occurring for the writes to the pipe between the
client/server processes or server and network driver to the NAS. I
suspect the latter because of the following data extracted from strace.
This data was taken for a run that failed. strace was attached to the
two BackupPC_dump processes that were running. You can see that the
reads were occurring from the NAS share (/media/Backup/BackupPC/pc/...)
and a write process [write(9<socket:[258436]>,] to a socket received the
EPIPE signal. There's also an alarm(72000) that may be significant.
-------
5677 12:37:51.243532
read(6</media/Backup/BackupPC/pc/johned-linux-vbox/5/fDrive1/f.virtualbox/fMachines/fWin
10 Pro x64 VM07/fWin 10 Pro x64 VM07-disk1.vdi>, <unfinished ...>
5671 12:37:51.244472 alarm(72000) = 72000
5671 12:37:51.244625 select(16, [7<socket:[259570]>],
[9<socket:[258436]>], [7<socket:[259570]> 9<socket:[258436]>], NULL) = 1
(out [9])
5671 12:37:51.244804 write(9<socket:[258436]>,
"\330\24\352\332U\367\0214?\213=tP
\v6\271TV\31z\342X\271\220/\326\"x\355\345\37"..., 35328) = -1 EPIPE
(Broken pipe)
5671 12:37:51.244912 --- SIGPIPE {si_signo=SIGPIPE,
si_code=SI_USER, si_pid=5671, si_uid=122} ---
5671 12:37:51.244946 rt_sigreturn() = -1 EPIPE (Broken pipe)
5
------
I've attached a file with more of the trace. I have a much longer file
with the last 10 minutes of the run before the failure. The rsync
process always fails two or three seconds longer than 300 seconds. I was
hoping that someone with knowledge of the internals of BackupPC could
chime in and shed some light on what's happening and why.
5677 12:37:51.238026
read(6</media/Backup/BackupPC/pc/johned-linux-vbox/5/fDrive1/f.virtualbox/fMachines/fWin
10 Pro x64 VM07/fWin 10 Pro x64 VM07-disk1.vdi>,
"G\0e\0t\0P\0r\0o\0t\0o\0c\0o\0l\0M\0a\0n\0a\0g\0"..., 65536) = 65536
5677 12:37:51.239296
read(6</media/Backup/BackupPC/pc/johned-linux-vbox/5/fDrive1/f.virtualbox/fMachines/fWin
10 Pro x64 VM07/fWin 10 Pro x64 VM07-disk1.vdi>,
"\205\300\213\370utH\213NHL\215\5\277@\376\377H\213\323\350g\204\377\377\205\300\213\370uNH"...,
65536) = 65536
5677 12:37:51.240156
read(6</media/Backup/BackupPC/pc/johned-linux-vbox/5/fDrive1/f.virtualbox/fMachines/fWin
10 Pro x64 VM07/fWin 10 Pro x64 VM07-disk1.vdi>,
"\213E\10H\211A\10I\213E\20H\211A\20H\215\214$\260\0\0\0H\213\1H\211\2H\213A"...,
65536) = 65536
5677 12:37:51.241665
read(6</media/Backup/BackupPC/pc/johned-linux-vbox/5/fDrive1/f.virtualbox/fMachines/fWin
10 Pro x64 VM07/fWin 10 Pro x64 VM07-disk1.vdi>,
"H\307\301\377\377\377\377H\17@\301H\213\310\350=\2\3\0H\205\300H\213\330u\7\277\16\0\7\200"...,
65536) = 65536
5677 12:37:51.242537
read(6</media/Backup/BackupPC/pc/johned-linux-vbox/5/fDrive1/f.virtualbox/fMachines/fWin
10 Pro x64 VM07/fWin 10 Pro x64 VM07-disk1.vdi>,
"\2\273z\0\7\200f\211)\205\333u\17H\215\214$`\6\0\0\350V\370\377\377\213\330H\213\r%"...,
65536) = 65536
5677 12:37:51.243532
read(6</media/Backup/BackupPC/pc/johned-linux-vbox/5/fDrive1/f.virtualbox/fMachines/fWin
10 Pro x64 VM07/fWin 10 Pro x64 VM07-disk1.vdi>, <unfinished ...>
5671 12:37:51.244472 alarm(72000) = 72000
5671 12:37:51.244625 select(16, [7<socket:[259570]>], [9<socket:[258436]>],
[7<socket:[259570]> 9<socket:[258436]>], NULL) = 1 (out [9])
5671 12:37:51.244804 write(9<socket:[258436]>,
"\330\24\352\332U\367\0214?\213=tP
\v6\271TV\31z\342X\271\220/\326\"x\355\345\37"..., 35328) = -1 EPIPE (Broken
pipe)
5671 12:37:51.244912 --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER,
si_pid=5671, si_uid=122} ---
5671 12:37:51.244946 rt_sigreturn() = -1 EPIPE (Broken pipe)
5671 12:37:51.244989 rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
5671 12:37:51.245053 rt_sigaction(SIGPIPE, NULL, {0x7f9b72f51960, [],
SA_RESTORER, 0x7f9b72b25cb0}, 8) = 0
5671 12:37:51.245180 stat("/etc/localtime", {st_mode=S_IFREG|0644,
st_size=2819, ...}) = 0
5671 12:37:51.245282
write(3</media/Backup/BackupPC/pc/johned-linux-vbox/LOG.012017>, "2017-01-19
12:37:51 Aborting bac"..., 57 <unfinished ...>
5677 12:37:51.245794 <... read resumed>
"f\211\20H\203\300\2I\203\350\1u\351\353\5M\205\300u\tH\203\350\2\273z\0\7\200fD\211"...,
65536) = 65536
5677 12:37:51.246147
read(6</media/Backup/BackupPC/pc/johned-linux-vbox/5/fDrive1/f.virtualbox/fMachines/fWin
10 Pro x64 VM07/fWin 10 Pro x64 VM07-disk1.vdi>,
"\213\310\213\320\17\272\351\36\360\17\261\v;\302u\360H\211t$P\270\261\23;\261H\211|$X3"...,
65536) = 65536
5671 12:37:51.246846 <... write resumed> ) = 57
------------------------------------------------------------------------------
Check out the vibrant tech community on one of the world's most
engaging tech sites, SlashDot.org! http://sdm.link/slashdot
_______________________________________________
BackupPC-users mailing list
BackupPC-users@lists.sourceforge.net
List: https://lists.sourceforge.net/lists/listinfo/backuppc-users
Wiki: http://backuppc.wiki.sourceforge.net
Project: http://backuppc.sourceforge.net/
