Chris,
Was there ever any resolution to your problem? I'm having the same
problem with amanda 2.5.1p3 and GNU tar 1.16 hanging on one of my
Solaris 8 servers. The funny thing is that it only hangs when tarring
up one of the disks...my root filesystem. 5 other disks on the same
server get backed with gtar up just fine.
It seems to try dumping the / filesystem twice before abandoning it due
to data timeout. I have dtimeout set to 3600 in amanda.conf. However,
the tar procs on the client keep running and never finish or die and the
file at /usr/local/var/amanda/gnutar-lists/lci-nms-pri.lci.com__0.new on
the client has a 0 size.
Any ideas?
Here are some log files:
========================================================================
===============
(From Amanda 2.5.1p3 server
/usr/local/etc/amanda/DailySet2/log.20070426040001.0)
========================================================================
===============
FAIL dumper lci-nms-pri.lci.com / 20070426040001 0 [data timeout]
sendbackup: start [lci-nms-pri.lci.com:/ level 0]
sendbackup: info BACKUP=/usr/local/bin/tar
sendbackup: info RECOVER_CMD=/usr/local/bin/tar -f - ...
sendbackup: info end
PARTIAL chunker lci-nms-pri.lci.com / 20070426040001 0 [sec 3657.354 kb
3340 kps 0.9]
.
.
.
PARTIAL chunker lci-nms-pri.lci.com / 20070426040001 0 [sec 3634.416 kb
3340 kps 0.9]
FAIL dumper lci-nms-pri.lci.com / 20070426040001 0 [data timeout]
sendbackup: start [lci-nms-pri.lci.com:/ level 0]
sendbackup: info BACKUP=/usr/local/bin/tar
sendbackup: info RECOVER_CMD=/usr/local/bin/tar -f - ...
sendbackup: info end
========================================================================
===============
(From Amanda 2.5.1p3 client
/var/log/amanda/debug/client/DailySet2/sendbackup.20070426040348.debug)
========================================================================
===============
sendbackup: debug 1 pid 11419 ruid 88888 euid 88888: start at Thu Apr 26
04:03:48 2007
sendbackup: version 2.5.1p3
Reading conf file "/usr/local/etc/amanda/amanda-client.conf".
Could not open conf file
"/usr/local/etc/amanda/DailySet2/amanda-client.conf": No such file or
directory
sendbackup: debug 1 pid 11419 ruid 88888 euid 88888: rename at Thu Apr
26 04:03:48 2007
sendbackup req: <GNUTAR / 0 1970:1:1:0:0:0 OPTIONS
|;auth=ssh;index;exclude-file=*/*.log;exclude-file=*/messages;exclude-fi
le=*/messages.?;exclu
de-file=*/socket*;exclude-file=*gnutar-lists*;exclude-list=/usr/local/et
c/amanda/exclude_from_backups.txt;>
parsed request as: program `GNUTAR'
disk `/'
device `/'
level 0
since 1970:1:1:0:0:0
options
`|;auth=ssh;index;exclude-file=*/*.log;exclude-file=*/messages;exclude-f
ile=*/messages.?;exclude-file=*/socket*;exclud
e-file=*gnutar-lists*;exclude-list=/usr/local/etc/amanda/exclude_from_ba
ckups.txt;'
sendbackup: start: lci-nms-pri.lci.com:/ lev 0
sendbackup-gnutar: time 0.033: doing level 0 dump as listed-incremental
to '/usr/local/var/amanda/gnutar-lists/lci-nms-pri.lci.com__0.new'
sendbackup-gnutar: time 0.035: doing level 0 dump from date: 1970-01-01
0:00:00 GMT
sendbackup: time 0.043: spawning /usr/local/libexec/runtar in pipeline
sendbackup: argument list: runtar DailySet2 gtar --create --file -
--directory / --one-file-system --listed-incremental
/usr/local/var/amanda/gnuta
r-lists/lci-nms-pri.lci.com__0.new --sparse --ignore-failed-read
--totals --exclude-from /tmp/amanda/sendbackup._.20070426040348.exclude
.
sendbackup: time 0.048: started index creator: "/usr/local/bin/tar -tf -
2>/dev/null | sed -e 's/^\.//'"
sendbackup-gnutar: time 0.048: /usr/local/libexec/runtar: pid 11422
sendbackup: time 0.049: started backup
(notice no finish time)
========================================================================
===============
(From Amanda 2.5.1p3 client
/var/log/amanda/debug/amandad/amandad.20070426040348.debug)
========================================================================
===============
amandad: debug 1 pid 11418 ruid 88888 euid 88888: start at Thu Apr 26
04:03:48 2007
security_getdriver(name=ssh) returns ff2d8700
amandad: version 2.5.1p3
amandad: build: VERSION="Amanda-2.5.1p3"
amandad: BUILT_DATE="Wed Apr 11 12:17:37 EDT 2007"
amandad: BUILT_MACH="SunOS arl-collect1 5.8 Generic_117350-46
sun4u sparc SUNW,Sun-Fire-V240"
amandad: CC="/usr/local/bin/gcc"
amandad: CONFIGURE_COMMAND="'./configure' '--with-user=amanda'
'--with-group=backups'
'--with-index-server=arl-fratm-backups.qintra.com' '--
with-tape-server=arl-fratm-backups.qintra.com'
'--with-gnutar=/usr/local/bin/tar'
'--with-gnutar-listdir=/usr/local/var/amanda/gnutar-lists' '--wit
h-assertions=yes' '--with-debugging=/var/log/amanda/debug'
'--with-fqdn=yes' '--with-pid-debug-files=yes'
'--without-built-manpages' '--with-ssh-se
curity' '--with-gnu-ld=yes' '--without-termcap' '--without-ltermcap'
'--without-LIBTERMCAP' '--with-ncurses=yes' '--with-lncurses=yes'
'--with-LIBN
CURSES=yes' '--without-server'"
amandad: paths: bindir="/usr/local/bin" sbindir="/usr/local/sbin"
amandad: libexecdir="/usr/local/libexec" mandir="/usr/local/man"
amandad: AMANDA_TMPDIR="/tmp/amanda"
amandad: AMANDA_DBGDIR="/var/log/amanda/debug"
amandad: CONFIG_DIR="/usr/local/etc/amanda"
DEV_PREFIX="/dev/dsk/"
amandad: RDEV_PREFIX="/dev/rdsk/" DUMP="/usr/sbin/ufsdump"
amandad: RESTORE="/usr/sbin/ufsrestore" VDUMP=UNDEF
VRESTORE=UNDEF
amandad: XFSDUMP=UNDEF XFSRESTORE=UNDEF VXDUMP=UNDEF
VXRESTORE=UNDEF
amandad: SAMBA_CLIENT=UNDEF GNUTAR="/usr/local/bin/tar"
amandad: COMPRESS_PATH="/usr/bin/gzip"
amandad: UNCOMPRESS_PATH="/usr/bin/gzip" LPRCMD="/usr/ucb/lpr"
amandad: MAILER="/usr/ucb/Mail"
amandad: listed_incr_dir="/usr/local/var/amanda/gnutar-lists"
amandad: defs: DEFAULT_SERVER="arl-fratm-backups.qintra.com"
amandad: DEFAULT_CONFIG="DailySet1"
amandad: DEFAULT_TAPE_SERVER="arl-fratm-backups.qintra.com"
HAVE_MMAP
amandad: HAVE_SYSVSHM LOCKING=POSIX_FCNTL SETPGRP_VOID ASSERTIONS
amandad: DEBUG_CODE AMANDA_DEBUG_DAYS=4 BSD_SECURITY RSH_SECURITY
amandad: USE_AMANDAHOSTS CLIENT_LOGIN="amanda" FORCE_USERID
HAVE_GZIP
amandad: COMPRESS_SUFFIX=".gz" COMPRESS_FAST_OPT="--fast"
amandad: COMPRESS_BEST_OPT="--best" UNCOMPRESS_OPT="-dc"
security_handleinit(handle=27378, driver=ff2d8700 (SSH))
security_streaminit(stream=2b7d8, driver=ff2d8700 (SSH))
amandad: time 0.001: accept recv REQ pkt:
<<<<<
SERVICE sendbackup
OPTIONS
features=fffffeff9ffeffffff7f;hostname=lci-nms-pri.lci.com;config=DailyS
et2;
GNUTAR / 0 1970:1:1:0:0:0 OPTIONS
|;auth=ssh;index;exclude-file=*/*.log;exclude-file=*/messages;exclude-fi
le=*/messages.?;exclude-file=*/socket*;e
xclude-file=*gnutar-lists*;exclude-list=/usr/local/etc/amanda/exclude_fr
om_backups.txt;
>>>>>
amandad: time 0.002: creating new service: sendbackup
OPTIONS
features=fffffeff9ffeffffff7f;hostname=lci-nms-pri.lci.com;config=DailyS
et2;
GNUTAR / 0 1970:1:1:0:0:0 OPTIONS
|;auth=ssh;index;exclude-file=*/*.log;exclude-file=*/messages;exclude-fi
le=*/messages.?;exclude-file=*/socket*;e
xclude-file=*gnutar-lists*;exclude-list=/usr/local/etc/amanda/exclude_fr
om_backups.txt;
amandad: time 0.006: sending ACK pkt:
<<<<<
>>>>>
security_streaminit(stream=440b0, driver=ff2d8700 (SSH))
security_streaminit(stream=4c0f0, driver=ff2d8700 (SSH))
security_streaminit(stream=54130, driver=ff2d8700 (SSH))
amandad: time 0.081: sending REP pkt:
<<<<<
CONNECT DATA 499999 MESG 499998 INDEX 499997
OPTIONS features=fffffeff9ffeffffff7f;
>>>>>
amandad: time 0.106: received ACK pkt:
<<<<<
>>>>>
security_close(handle=27378, driver=ff2d8700 (SSH))
security_stream_close(2b7d8)
security_stream_seterr(440b0, EOF)
security_stream_seterr(4c0f0, EOF)
security_stream_seterr(54130, EOF)
( For the disks on the client that get backed up ok, the amanadad log
ends like this:)
amandad: time 0.107: received ACK pkt:
<<<<<
>>>>>
security_close(handle=27388, driver=ff2d8700 (SSH))
security_stream_close(2b7d8)
security_stream_close(54150)
security_stream_close(440d0)
security_stream_close(4c110)
amandad: time 7509.339: pid 10416 finish time Thu Apr 26 06:07:56 2007
========================================================================
===============
Thanks,
Ray
>From: Chris Cameron <chris.cameron AT netthruput DOT com>
>To: amanda-users AT amanda DOT org
>Date: Mar 29 2007 - 10:39am
>
>
>
>sendbackup:
>
>sendbackup: debug 1 pid 28355 ruid 2 euid 2: start at Thu Mar 29
>07:15:09 2007
>sendbackup: version 2.5.1p3
>Could not open conf file "/etc/amanda/amanda-client.conf": No such file
>or directory
>Could not open conf file "/etc/amanda/test/amanda-client.conf": No such
>file or directory
>sendbackup: debug 1 pid 28355 ruid 2 euid 2: rename at Thu Mar 29
>07:15:09 2007
>sendbackup req:
>parsed request as: program `GNUTAR'
>disk `/dev/raid0g'
>device `/dev/raid0g'
>level 0
>since 1970:1:1:0:0:0
>options
>`|;auth=BSD;compress-fast;encrypt-serv-cust=/opt/amanda/sbin/amcrypt-os
sl;server-decrypt-option=-d;index;'
>sendbackup: start: carp0:/dev/raid0g lev 0
>sendbackup: time 0.041: spawning /usr/bin/gzip in pipeline
>sendbackup: argument list: /usr/bin/gzip --fast
>sendbackup-gnutar: time 0.046: pid 31136: /usr/bin/gzip --fast
>sendbackup-gnutar: time 0.064: doing level 0 dump as listed-incremental
>to '/var/amanda/gnutar-lists/carp0_dev_raid0g_0.new'
>sendbackup-gnutar: time 0.069: doing level 0 dump from date: 1970-01-01
>0:00:00 GMT
>sendbackup: time 0.072: spawning /usr/local/libexec/runtar in pipeline
>sendbackup: argument list: runtar test gtar --create --file -
>--directory /home --one-file-system --listed-incremental
>/var/amanda/gnutar-lists/carp0_dev_raid0g_0.new --sparse
>--ignore-failed-read --totals .
>sendbackup-gnutar: time 0.129: /usr/local/libexec/runtar: pid 14139
>sendbackup: time 0.130: started backup
>sendbackup: time 0.139: started index creator: "/usr/local/bin/gtar -tf
>- 2>/dev/null | sed -e 's/^\.//'"
>
>
>sendbackup:
>-auth=bsd: debug 1 pid 9120 ruid 2 euid 2: start at Thu Mar 29 08:21:53
2007
>security_getdriver(name=BSD) returns 0x42af4038
>-auth=bsd: version 2.5.1p3
>-auth=bsd: build: VERSION="Amanda-2.5.1p3"
>-auth=bsd: BUILT_DATE="Mon Mar 26 08:10:30 MDT 2007"
>-auth=bsd: BUILT_MACH="OpenBSD carp1.netthruput.com 4.0 CARP#0
>sparc64"
>-auth=bsd: CC="gcc"
>-auth=bsd: CONFIGURE_COMMAND="'./configure' '--prefix=/usr/local'
>'--sysconfdir=/etc' '--localstatedir=/var' '--without-server'
>'--with-user=operator' '--with-group=operator'
>'--with-gnutar=/usr/local/bin/gtar'"
>-auth=bsd: paths: bindir="/usr/local/bin" sbindir="/usr/local/sbin"
>-auth=bsd: libexecdir="/usr/local/libexec" mandir="/usr/local/man"
>-auth=bsd: AMANDA_TMPDIR="/tmp/amanda" AMANDA_DBGDIR="/tmp/amanda"
>-auth=bsd: CONFIG_DIR="/etc/amanda" DEV_PREFIX="/dev/"
>-auth=bsd: RDEV_PREFIX="/dev/r" DUMP="/sbin/dump"
>-auth=bsd: RESTORE="/sbin/restore" VDUMP=UNDEF VRESTORE=UNDEF
>-auth=bsd: XFSDUMP=UNDEF XFSRESTORE=UNDEF VXDUMP=UNDEF
>VXRESTORE=UNDEF
>-auth=bsd: SAMBA_CLIENT=UNDEF GNUTAR="/usr/local/bin/gtar"
>-auth=bsd: COMPRESS_PATH="/usr/bin/gzip"
>-auth=bsd: UNCOMPRESS_PATH="/usr/bin/gzip" LPRCMD="/usr/bin/lpr"
>-auth=bsd: MAILER="/usr/bin/Mail"
>-auth=bsd: listed_incr_dir="/var/amanda/gnutar-lists"
>-auth=bsd: defs: DEFAULT_SERVER="carp1.netthruput.com"
>-auth=bsd: DEFAULT_CONFIG="DailySet1"
>-auth=bsd: DEFAULT_TAPE_SERVER="carp1.netthruput.com" HAVE_MMAP
>-auth=bsd: HAVE_SYSVSHM LOCKING=POSIX_FCNTL DEBUG_CODE
>-auth=bsd: AMANDA_DEBUG_DAYS=4 BSD_SECURITY RSH_SECURITY
>USE_AMANDAHOSTS
>-auth=bsd: CLIENT_LOGIN="operator" FORCE_USERID HAVE_GZIP
>-auth=bsd: COMPRESS_SUFFIX=".gz" COMPRESS_FAST_OPT="--fast"
>-auth=bsd: COMPRESS_BEST_OPT="--best" UNCOMPRESS_OPT="-dc"
>-auth=bsd: time 0.001: dgram_recv(dgram=0x42ef8960, timeout=0,
>fromaddr=0x42f08958)
>-auth=bsd: time 0.001: (sockaddr_in *)0x42f08958 = { 2, 906,
>192.168.120.50 }
>security_handleinit(handle=0x45a96000, driver=0x42af4038 (BSD))
>-auth=bsd: time 0.006: accept recv REQ pkt:
>>>>>
>-auth=bsd: time 0.007: creating new service: noop
>OPTIONS features=fffffeff9ffeffffff7f;
>
>-auth=bsd: time 0.012: sending ACK pkt:
>>>>>
>-auth=bsd: dgram_send_addr(addr=0xfffffffffffee1b0, dgram=0x42ef8960)
>-auth=bsd: time 0.013: (sockaddr_in *)0xfffffffffffee1b0 = { 2, 906,
>192.168.120.50 }
>-auth=bsd: dgram_send_addr: 0x42ef8960->socket = 0
>-auth=bsd: time 0.056: sending REP pkt:
>>>>>
>-auth=bsd: dgram_send_addr(addr=0xfffffffffffee340, dgram=0x42ef8960)
>-auth=bsd: time 0.056: (sockaddr_in *)0xfffffffffffee340 = { 2, 906,
>192.168.120.50 }
>-auth=bsd: dgram_send_addr: 0x42ef8960->socket = 0
>-auth=bsd: time 0.057: dgram_recv(dgram=0x42ef8960, timeout=0,
>fromaddr=0x42f08958)
>-auth=bsd: time 0.057: (sockaddr_in *)0x42f08958 = { 2, 906,
>192.168.120.50 }
>-auth=bsd: time 0.057: received ACK pkt:
>>>>>
>security_close(handle=0x45a96000, driver=0x42af4038 (BSD))
>-auth=bsd: time 0.062: dgram_recv(dgram=0x42ef8960, timeout=0,
>fromaddr=0x42f08958)
>-auth=bsd: time 0.062: (sockaddr_in *)0x42f08958 = { 2, 906,
>192.168.120.50 }
>security_handleinit(handle=0x47c62000, driver=0x42af4038 (BSD))
>-auth=bsd: time 0.064: accept recv REQ pkt:
>>>>>
>-auth=bsd: time 0.064: creating new service: sendsize
>OPTIONS
features=fffffeff9ffeffffff7f;maxdumps=1;hostname=carp1;config=test;
>GNUTAR /dev/raid0g 0 1970:1:1:0:0:0 -1 OPTIONS
>|;auth=BSD;compress-fast;encrypt-serv-cust=/opt/amanda/sbin/amcrypt-oss
l;server-decrypt-option=-d;index;
>
>-auth=bsd: time 0.071: sending ACK pkt:
>>>>>
>-auth=bsd: dgram_send_addr(addr=0xfffffffffffee1b0, dgram=0x42ef8960)
>-auth=bsd: time 0.072: (sockaddr_in *)0xfffffffffffee1b0 = { 2, 906,
>192.168.120.50 }
>-auth=bsd: dgram_send_addr: 0x42ef8960->socket = 0
>-auth=bsd: time 0.136: sending PREP pkt:
>>>>>
>-auth=bsd: dgram_send_addr(addr=0xfffffffffffee320, dgram=0x42ef8960)
>-auth=bsd: time 0.137: (sockaddr_in *)0xfffffffffffee320 = { 2, 906,
>192.168.120.50 }
>-auth=bsd: dgram_send_addr: 0x42ef8960->socket = 0
>-auth=bsd: time 0.169: sending REP pkt:
>>>>>
>-auth=bsd: dgram_send_addr(addr=0xfffffffffffee340, dgram=0x42ef8960)
>-auth=bsd: time 0.169: (sockaddr_in *)0xfffffffffffee340 = { 2, 906,
>192.168.120.50 }
>-auth=bsd: dgram_send_addr: 0x42ef8960->socket = 0
>-auth=bsd: time 0.169: dgram_recv(dgram=0x42ef8960, timeout=0,
>fromaddr=0x42f08958)
>-auth=bsd: time 0.169: (sockaddr_in *)0x42f08958 = { 2, 906,
>192.168.120.50 }
>-auth=bsd: time 0.169: received ACK pkt:
>>>>>
>security_close(handle=0x47c62000, driver=0x42af4038 (BSD))
>-auth=bsd: time 30.184: pid 9120 finish time Thu Mar 29 08:22:24 2007
>
>
>
>Thanks,
>Chris
>
>
>Jean-Louis Martineau wrote:
>> The 'Illegel seek' is not a problem.
>> The sendsize is working correctly, the problem is with sendbackup
>>
>> Could you post the sendbackup and amandad debug files?
>>
>> Jean-Louis
>>
>> Chris Cameron wrote:
>>> I have Amanda 2.5.1p3 running on Solaris 8 for the server, and the
>>> client is the same version running on OpenBSD 4.0.
>>>
>>> Using GNUTAR, the dump times out. The error on the client machine
is:
>>>
>>> sendsize[3860]: time 0.058: waiting for any estimate child: 1
running
>>> sendsize[28668]: time 0.061: calculating for amname /dev/raid0g,
>>> dirname /home, spindle -1
>>> sendsize[28668]: time 0.063: getting size via gnutar for /dev/raid0g
>>> level 0
>>> sendsize[28668]: time 0.094: spawning /usr/local/libexec/runtar in
>>> pipeline
>>> sendsize[28668]: argument list: runtar test /usr/local/bin/gtar
>>> --create --file /dev/null --directory /home --one-file-system
>>> --listed-incremental /var/amanda/gnutar-lists/carp0_dev_raid0g_0.new
>>> --sparse --ignore-failed-read --totals .
>>> sendsize[28668]: time 0.337: Total bytes written: 15718400 (15MiB,
>>> 124MiB/s)
>>> sendsize[28668]: time 0.342: .....
>>> sendsize[28668]: estimate time for /dev/raid0g level 0: 0.248
>>> sendsize[28668]: estimate size for /dev/raid0g level 0: 15350 KB
>>> sendsize[28668]: time 0.342: waiting for runtar "/dev/raid0g" child
>>> sendsize[28668]: time 0.347: after runtar /dev/raid0g wait
>>> gnutar_calc_estimates: warning - seek failed: Illegal seek
>>> sendsize[28668]: time 0.365: done with amname /dev/raid0g dirname
>>> /home spindle -1
>>> sendsize[3860]: time 0.370: child 28668 terminated normally
>>>
>>>
>>>
>>> The tar part seems to work, as I can also run it just at a command
>>> line without error. However the message:
>>>
>>> warning - seek failed: Illegal seek
>>>
>>> Doesn't seem good.
>>>
>>>
>>> In the report email:
>>>
>>> carp0 /dev/raid0g lev 0 FAILED [data timeout]
>>> carp0 /dev/raid0g lev 0 FAILED [too many dumper retry:
>>> "[request failed: timeout waiting for ACK]"]
>>> carp0 /dev/raid0g lev 0 FAILED [cannot read header: got 0
>>> instead of 32768]
>>>
>>>
>>> When amdump gives up, it leaves the following processes on the
client
>>> machine:
>>>
>>> operator 30460 0.0 0.2 968 2200 ?? Is 9:09AM 0:00.13 amandad
>>> operator 10245 0.0 0.2 816 2240 ?? I 9:10AM 0:00.08
>>> /usr/local/libexec/sendbackup amandad bsd
>>> operator 15664 0.0 0.1 824 1528 ?? I 9:10AM 0:00.04
>>> /usr/bin/gzip --fast
>>> operator 31389 0.0 0.1 816 1392 ?? I 9:10AM 0:00.02
>>> /usr/local/libexec/sendbackup amandad bsd
>>> operator 22560 0.0 0.1 768 576 ?? I 9:10AM 0:00.01 sh
>>> -c sh
>>> operator 28437 0.0 0.1 432 1192 ?? I 9:10AM 0:00.05 sed
>>> -e s/^\\.//
>>> operator 18449 0.0 0.1 792 648 ?? I 9:10AM 0:00.03
>>> /usr/local/bin/gtar -tf -
>>>
>>>
>>> Watching tcpdump I don't see any obvious retrying going on. I have a
>>> whack of other Solaris 8 machines that don't have any problem with
tar
>>> (1.16)
>>>
>>>
>>> Anyone know what I've done wrong here?
>>>
>>>
>>> Thanks,
>>> Chris
Raymond Lee
Lead Systems Engineer - Network Services
Qwest Services Corporation
4250 N Fairfax Dr, 4E193
Arlington VA 22203
(703) 363-3521 (Office)
(202) 297-0630 (Mobile)
rlee128 at skytel dot com (pager)
This communication is the property of Qwest and may contain confidential or
privileged information. Unauthorized use of this communication is strictly
prohibited and may be unlawful. If you have received this communication
in error, please immediately notify the sender by reply e-mail and destroy
all copies of the communication and any attachments.
|
