OK,
So tonight the backups complete and strangely I get this in the email
report for the usually failed DLE :
FAILURE AND STRANGE DUMP SUMMARY:
qtvsrv1.xxxx /usr lev 0 FAILED [cannot read header: got 0
instead of 32768]
qtvsrv1.xxxx /usr lev 0 was successfully retried
Dumper logs are covered in this :
dumper: connect_port: Try port 1025: Available -
dumper: connected to 127.0.0.1.35862
dumper: our side is 0.0.0.0.1025
dumper: try_socksize: send buffer size is 65536
security_getdriver(name=krb5) returns 0x5d60c0
security_handleinit(handle=0x8382208, driver=0x5d60c0 (krb5))
security_streaminit(stream=0x8382280, driver=0x5d60c0 (krb5))
dumper: connect_port: Try port 1025: Available -
dumper: connected to 172.16.1.9.10082
dumper: our side is 0.0.0.0.1025
dumper: try_socksize: send buffer size is 65536
dumper: try_socksize: receive buffer size is 65536
security_seterror(handle=0x8382208, driver=0x5d60c0 (krb5) error=krb5
write error to qtvsrv1.xxxx: Broken pipe)
security_close(handle=0x8382208, driver=0x5d60c0 (krb5))
security_stream_close(0x8382280)
security_handleinit(handle=0x835ec68, driver=0x5d60c0 (krb5))
security_streaminit(stream=0x8382280, driver=0x5d60c0 (krb5))
security_seterror(handle=0x835ec68, driver=0x5d60c0 (krb5) error=krb5
write error to qtvsrv1.xxxx: Broken pipe)
security_close(handle=0x835ec68, driver=0x5d60c0 (krb5))
security_stream_close(0x8382280)
security_handleinit(handle=0x835ec68, driver=0x5d60c0 (krb5))
security_streaminit(stream=0x8382280, driver=0x5d60c0 (krb5))
security_seterror(handle=0x835ec68, driver=0x5d60c0 (krb5) error=krb5
write error to qtvsrv1.xxxx: Broken pipe)
security_close(handle=0x835ec68, driver=0x5d60c0 (krb5))
security_stream_close(0x8382280)
Now, at this point I apologise, because here are my amandad debugs of
the complete backup session :
[EMAIL PROTECTED] amandad]# cat amandad.20070205235902.debug
amandad: debug 1 pid 12769 ruid 0 euid 0: start at Mon Feb 5
23:59:02 2007
security_getdriver(name=krb5) returns 0x1cc0c0
amandad: version 2.5.1p2
amandad: build: VERSION="Amanda-2.5.1p2"
amandad: BUILT_DATE="Thu Feb 1 03:24:00 GMT 2007"
amandad: BUILT_MACH="Linux qa-apps 2.6.9-42.ELsmp #1 SMP Wed
Jul 12 23:27:17 EDT 2006 i686 i686 i386 GNU/Linux"
amandad: CC="gcc"
amandad: CONFIGURE_COMMAND="'./configure' '--with-krb5-
security' '--with-user=amanda' '--with-group=backup' '--with-
config=DailySet1' '--sbindir=/usr/sbin' '--libexecdir=/usr/libexec'
'--libdir=/usr/lib' '--with-configdir=/etc/amanda' '--with-gnutar-
listdir=/var/amanda/gnutar-lists' '--mandir=/usr/share/man'"
amandad: paths: bindir="/usr/local/bin" sbindir="/usr/sbin"
amandad: libexecdir="/usr/libexec" mandir="/usr/share/man"
amandad: AMANDA_TMPDIR="/tmp/amanda" AMANDA_DBGDIR="/tmp/amanda"
amandad: CONFIG_DIR="/etc/amanda" DEV_PREFIX="/dev/"
amandad: RDEV_PREFIX="/dev/r" DUMP="/sbin/dump"
amandad: RESTORE="/sbin/restore" VDUMP=UNDEF VRESTORE=UNDEF
amandad: XFSDUMP=UNDEF XFSRESTORE=UNDEF VXDUMP=UNDEF
VXRESTORE=UNDEF
amandad: SAMBA_CLIENT="/usr/bin/smbclient" GNUTAR="/bin/gtar"
amandad: COMPRESS_PATH="/bin/gzip" UNCOMPRESS_PATH="/bin/gzip"
amandad: LPRCMD="/usr/bin/lpr" MAILER="/usr/bin/Mail"
amandad: listed_incr_dir="/var/amanda/gnutar-lists"
amandad: defs: DEFAULT_SERVER="qa-apps" DEFAULT_CONFIG="DailySet1"
amandad: DEFAULT_TAPE_SERVER="qa-apps" HAVE_MMAP HAVE_SYSVSHM
amandad: LOCKING=POSIX_FCNTL SETPGRP_VOID DEBUG_CODE
amandad: AMANDA_DEBUG_DAYS=4 BSD_SECURITY KRB5_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=0x9199440, driver=0x1cc0c0 (krb5))
security_streaminit(stream=0x91994a8, driver=0x1cc0c0 (krb5))
amandad: time 0.103: accept recv REQ pkt:
<<<<<
SERVICE noop
OPTIONS features=fffffeff9ffeffffff7f;
>>>>>
amandad: time 0.103: creating new service: noop
OPTIONS features=fffffeff9ffeffffff7f;
amandad: time 0.105: sending ACK pkt:
<<<<<
>>>>>
amandad: time 0.123: sending REP pkt:
<<<<<
OPTIONS features=fffffeff9ffeffffff7f;
>>>>>
amandad: time 0.530: received ACK pkt:
<<<<<
>>>>>
security_close(handle=0x9199440, driver=0x1cc0c0 (krb5))
security_stream_close(0x91994a8)
security_handleinit(handle=0x91993c8, driver=0x1cc0c0 (krb5))
security_streaminit(stream=0x9199ae0, driver=0x1cc0c0 (krb5))
amandad: time 1.054: accept recv REQ pkt:
<<<<<
SERVICE sendsize
OPTIONS
features=fffffeff9ffeffffff7f;maxdumps=1;hostname=qtvsrv1.xxxx;config=Da
ilySet1;
GNUTAR /usr 0 1970:1:1:0:0:0 -1 OPTIONS |;auth=krb5;compress-
fast;index;exclude-file=./public;exclude-file=./transfer;exclude-
file=./tmp/*;exclude-file=./var/tmp/*;exclude-file=./Network/Servers/
*;exclude-file=*/*.ts;exclude-file=*/*.mpg;exclude-file=*/
*.mpeg;exclude-file=*/*.mp4;exclude-file=./proc;exclude-file=./
sys;exclude-file=./vstore;exclude-file=./home/perforce/backup/
*;exclude-file=./lon_transfer/*;exclude-file=./lon_public/*;exclude-
file=./downloads/*;exclude-file=./u01/*;
GNUTAR / 0 1970:1:1:0:0:0 -1 OPTIONS |;auth=krb5;compress-
fast;index;exclude-file=./public;exclude-file=./transfer;exclude-
file=./tmp/*;exclude-file=./var/tmp/*;exclude-file=./Network/Servers/
*;exclude-file=*/*.ts;exclude-file=*/*.mpg;exclude-file=*/
*.mpeg;exclude-file=*/*.mp4;exclude-file=./proc;exclude-file=./
sys;exclude-file=./vstore;exclude-file=./home/perforce/backup/
*;exclude-file=./lon_transfer/*;exclude-file=./lon_public/*;exclude-
file=./downloads/*;exclude-file=./u01/*;
GNUTAR / 1 2007:2:1:23:33:49 -1 OPTIONS |;auth=krb5;compress-
fast;index;exclude-file=./public;exclude-file=./transfer;exclude-
file=./tmp/*;exclude-file=./var/tmp/*;exclude-file=./Network/Servers/
*;exclude-file=*/*.ts;exclude-file=*/*.mpg;exclude-file=*/
*.mpeg;exclude-file=*/*.mp4;exclude-file=./proc;exclude-file=./
sys;exclude-file=./vstore;exclude-file=./home/perforce/backup/
*;exclude-file=./lon_transfer/*;exclude-file=./lon_public/*;exclude-
file=./downloads/*;exclude-file=./u01/*;
>>>>>
amandad: time 1.054: creating new service: sendsize
OPTIONS
features=fffffeff9ffeffffff7f;maxdumps=1;hostname=qtvsrv1.xxxx;config=Da
ilySet1;
GNUTAR /usr 0 1970:1:1:0:0:0 -1 OPTIONS |;auth=krb5;compress-
fast;index;exclude-file=./public;exclude-file=./transfer;exclude-
file=./tmp/*;exclude-file=./var/tmp/*;exclude-file=./Network/Servers/
*;exclude-file=*/*.ts;exclude-file=*/*.mpg;exclude-file=*/
*.mpeg;exclude-file=*/*.mp4;exclude-file=./proc;exclude-file=./
sys;exclude-file=./vstore;exclude-file=./home/perforce/backup/
*;exclude-file=./lon_transfer/*;exclude-file=./lon_public/*;exclude-
file=./downloads/*;exclude-file=./u01/*;
GNUTAR / 0 1970:1:1:0:0:0 -1 OPTIONS |;auth=krb5;compress-
fast;index;exclude-file=./public;exclude-file=./transfer;exclude-
file=./tmp/*;exclude-file=./var/tmp/*;exclude-file=./Network/Servers/
*;exclude-file=*/*.ts;exclude-file=*/*.mpg;exclude-file=*/
*.mpeg;exclude-file=*/*.mp4;exclude-file=./proc;exclude-file=./
sys;exclude-file=./vstore;exclude-file=./home/perforce/backup/
*;exclude-file=./lon_transfer/*;exclude-file=./lon_public/*;exclude-
file=./downloads/*;exclude-file=./u01/*;
GNUTAR / 1 2007:2:1:23:33:49 -1 OPTIONS |;auth=krb5;compress-
fast;index;exclude-file=./public;exclude-file=./transfer;exclude-
file=./tmp/*;exclude-file=./var/tmp/*;exclude-file=./Network/Servers/
*;exclude-file=*/*.ts;exclude-file=*/*.mpg;exclude-file=*/
*.mpeg;exclude-file=*/*.mp4;exclude-file=./proc;exclude-file=./
sys;exclude-file=./vstore;exclude-file=./home/perforce/backup/
*;exclude-file=./lon_transfer/*;exclude-file=./lon_public/*;exclude-
file=./downloads/*;exclude-file=./u01/*;
amandad: time 1.057: sending ACK pkt:
<<<<<
>>>>>
amandad: time 1.107: sending PREP pkt:
<<<<<
OPTIONS features=fffffeff9ffeffffff7f;
>>>>>
amandad: time 4.831: sending PREP pkt:
<<<<<
OPTIONS features=fffffeff9ffeffffff7f;
/ 0 SIZE 375090
>>>>>
amandad: time 5.505: sending PREP pkt:
<<<<<
OPTIONS features=fffffeff9ffeffffff7f;
/ 0 SIZE 375090
/ 1 SIZE 14890
>>>>>
amandad: time 30.963: sending PREP pkt:
<<<<<
OPTIONS features=fffffeff9ffeffffff7f;
/ 0 SIZE 375090
/ 1 SIZE 14890
/usr 0 SIZE 1597520
>>>>>
amandad: time 30.964: sending REP pkt:
<<<<<
OPTIONS features=fffffeff9ffeffffff7f;
/ 0 SIZE 375090
/ 1 SIZE 14890
/usr 0 SIZE 1597520
>>>>>
amandad: time 30.964: received ACK pkt:
<<<<<
>>>>>
security_close(handle=0x91993c8, driver=0x1cc0c0 (krb5))
security_stream_close(0x9199ae0)
amandad: time 60.960: pid 12769 finish time Tue Feb 6 00:00:03 2007
[EMAIL PROTECTED] amandad]# cat amandad.20070206001731.debug
amandad: debug 1 pid 13126 ruid 0 euid 0: start at Tue Feb 6
00:17:31 2007
security_getdriver(name=krb5) returns 0x1ce0c0
amandad: version 2.5.1p2
amandad: build: VERSION="Amanda-2.5.1p2"
amandad: BUILT_DATE="Thu Feb 1 03:24:00 GMT 2007"
amandad: BUILT_MACH="Linux qa-apps 2.6.9-42.ELsmp #1 SMP Wed
Jul 12 23:27:17 EDT 2006 i686 i686 i386 GNU/Linux"
amandad: CC="gcc"
amandad: CONFIGURE_COMMAND="'./configure' '--with-krb5-
security' '--with-user=amanda' '--with-group=backup' '--with-
config=DailySet1' '--sbindir=/usr/sbin' '--libexecdir=/usr/libexec'
'--libdir=/usr/lib' '--with-configdir=/etc/amanda' '--with-gnutar-
listdir=/var/amanda/gnutar-lists' '--mandir=/usr/share/man'"
amandad: paths: bindir="/usr/local/bin" sbindir="/usr/sbin"
amandad: libexecdir="/usr/libexec" mandir="/usr/share/man"
amandad: AMANDA_TMPDIR="/tmp/amanda" AMANDA_DBGDIR="/tmp/amanda"
amandad: CONFIG_DIR="/etc/amanda" DEV_PREFIX="/dev/"
amandad: RDEV_PREFIX="/dev/r" DUMP="/sbin/dump"
amandad: RESTORE="/sbin/restore" VDUMP=UNDEF VRESTORE=UNDEF
amandad: XFSDUMP=UNDEF XFSRESTORE=UNDEF VXDUMP=UNDEF
VXRESTORE=UNDEF
amandad: SAMBA_CLIENT="/usr/bin/smbclient" GNUTAR="/bin/gtar"
amandad: COMPRESS_PATH="/bin/gzip" UNCOMPRESS_PATH="/bin/gzip"
amandad: LPRCMD="/usr/bin/lpr" MAILER="/usr/bin/Mail"
amandad: listed_incr_dir="/var/amanda/gnutar-lists"
amandad: defs: DEFAULT_SERVER="qa-apps" DEFAULT_CONFIG="DailySet1"
amandad: DEFAULT_TAPE_SERVER="qa-apps" HAVE_MMAP HAVE_SYSVSHM
amandad: LOCKING=POSIX_FCNTL SETPGRP_VOID DEBUG_CODE
amandad: AMANDA_DEBUG_DAYS=4 BSD_SECURITY KRB5_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=0x85b9f68, driver=0x1ce0c0 (krb5))
security_streaminit(stream=0x85ba4d8, driver=0x1ce0c0 (krb5))
amandad: time 0.732: accept recv REQ pkt:
<<<<<
SERVICE sendbackup
OPTIONS
features=fffffeff9ffeffffff7f;hostname=qtvsrv1.xxxx;config=DailySet1;
GNUTAR / 1 2007:2:1:23:33:49 OPTIONS |;auth=krb5;compress-
fast;index;exclude-file=./public;exclude-file=./transfer;exclude-
file=./tmp/*;exclude-file=./var/tmp/*;exclude-file=./Network/Servers/
*;exclude-file=*/*.ts;exclude-file=*/*.mpg;exclude-file=*/
*.mpeg;exclude-file=*/*.mp4;exclude-file=./proc;exclude-file=./
sys;exclude-file=./vstore;exclude-file=./home/perforce/backup/
*;exclude-file=./lon_transfer/*;exclude-file=./lon_public/*;exclude-
file=./downloads/*;exclude-file=./u01/*;
>>>>>
amandad: time 0.732: creating new service: sendbackup
OPTIONS
features=fffffeff9ffeffffff7f;hostname=qtvsrv1.xxxx;config=DailySet1;
GNUTAR / 1 2007:2:1:23:33:49 OPTIONS |;auth=krb5;compress-
fast;index;exclude-file=./public;exclude-file=./transfer;exclude-
file=./tmp/*;exclude-file=./var/tmp/*;exclude-file=./Network/Servers/
*;exclude-file=*/*.ts;exclude-file=*/*.mpg;exclude-file=*/
*.mpeg;exclude-file=*/*.mp4;exclude-file=./proc;exclude-file=./
sys;exclude-file=./vstore;exclude-file=./home/perforce/backup/
*;exclude-file=./lon_transfer/*;exclude-file=./lon_public/*;exclude-
file=./downloads/*;exclude-file=./u01/*;
amandad: time 0.734: sending ACK pkt:
<<<<<
>>>>>
security_streaminit(stream=0x85daee8, driver=0x1ce0c0 (krb5))
security_streaminit(stream=0x85eaf10, driver=0x1ce0c0 (krb5))
security_streaminit(stream=0x85faf38, driver=0x1ce0c0 (krb5))
amandad: time 0.783: sending REP pkt:
<<<<<
CONNECT DATA 4999 MESG 4998 INDEX 4997
OPTIONS features=fffffeff9ffeffffff7f;
>>>>>
amandad: time 0.784: received ACK pkt:
<<<<<
>>>>>
security_close(handle=0x85b9f68, driver=0x1ce0c0 (krb5))
security_stream_close(0x85ba4d8)
security_stream_close(0x85faf38)
security_stream_close(0x85daee8)
security_stream_close(0x85eaf10)
amandad: time 30.374: pid 13126 finish time Tue Feb 6 00:18:02 2007
[EMAIL PROTECTED] amandad]#
[EMAIL PROTECTED] amandad]#
[EMAIL PROTECTED] amandad]# cat amandad.20070206002404.debug
amandad: debug 1 pid 13217 ruid 0 euid 0: start at Tue Feb 6
00:24:04 2007
security_getdriver(name=krb5) returns 0xb7c0c0
amandad: version 2.5.1p2
amandad: build: VERSION="Amanda-2.5.1p2"
amandad: BUILT_DATE="Thu Feb 1 03:24:00 GMT 2007"
amandad: BUILT_MACH="Linux qa-apps 2.6.9-42.ELsmp #1 SMP Wed
Jul 12 23:27:17 EDT 2006 i686 i686 i386 GNU/Linux"
amandad: CC="gcc"
amandad: CONFIGURE_COMMAND="'./configure' '--with-krb5-
security' '--with-user=amanda' '--with-group=backup' '--with-
config=DailySet1' '--sbindir=/usr/sbin' '--libexecdir=/usr/libexec'
'--libdir=/usr/lib' '--with-configdir=/etc/amanda' '--with-gnutar-
listdir=/var/amanda/gnutar-lists' '--mandir=/usr/share/man'"
amandad: paths: bindir="/usr/local/bin" sbindir="/usr/sbin"
amandad: libexecdir="/usr/libexec" mandir="/usr/share/man"
amandad: AMANDA_TMPDIR="/tmp/amanda" AMANDA_DBGDIR="/tmp/amanda"
amandad: CONFIG_DIR="/etc/amanda" DEV_PREFIX="/dev/"
amandad: RDEV_PREFIX="/dev/r" DUMP="/sbin/dump"
amandad: RESTORE="/sbin/restore" VDUMP=UNDEF VRESTORE=UNDEF
amandad: XFSDUMP=UNDEF XFSRESTORE=UNDEF VXDUMP=UNDEF
VXRESTORE=UNDEF
amandad: SAMBA_CLIENT="/usr/bin/smbclient" GNUTAR="/bin/gtar"
amandad: COMPRESS_PATH="/bin/gzip" UNCOMPRESS_PATH="/bin/gzip"
amandad: LPRCMD="/usr/bin/lpr" MAILER="/usr/bin/Mail"
amandad: listed_incr_dir="/var/amanda/gnutar-lists"
amandad: defs: DEFAULT_SERVER="qa-apps" DEFAULT_CONFIG="DailySet1"
amandad: DEFAULT_TAPE_SERVER="qa-apps" HAVE_MMAP HAVE_SYSVSHM
amandad: LOCKING=POSIX_FCNTL SETPGRP_VOID DEBUG_CODE
amandad: AMANDA_DEBUG_DAYS=4 BSD_SECURITY KRB5_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=0x9363f68, driver=0xb7c0c0 (krb5))
security_streaminit(stream=0x93644d8, driver=0xb7c0c0 (krb5))
amandad: time 0.045: accept recv REQ pkt:
<<<<<
SERVICE sendbackup
OPTIONS
features=fffffeff9ffeffffff7f;hostname=qtvsrv1.xxxx;config=DailySet1;
GNUTAR /usr 0 1970:1:1:0:0:0 OPTIONS |;auth=krb5;compress-
fast;index;exclude-file=./public;exclude-file=./transfer;exclude-
file=./tmp/*;exclude-file=./var/tmp/*;exclude-file=./Network/Servers/
*;exclude-file=*/*.ts;exclude-file=*/*.mpg;exclude-file=*/
*.mpeg;exclude-file=*/*.mp4;exclude-file=./proc;exclude-file=./
sys;exclude-file=./vstore;exclude-file=./home/perforce/backup/
*;exclude-file=./lon_transfer/*;exclude-file=./lon_public/*;exclude-
file=./downloads/*;exclude-file=./u01/*;
>>>>>
amandad: time 0.045: creating new service: sendbackup
OPTIONS
features=fffffeff9ffeffffff7f;hostname=qtvsrv1.xxxx;config=DailySet1;
GNUTAR /usr 0 1970:1:1:0:0:0 OPTIONS |;auth=krb5;compress-
fast;index;exclude-file=./public;exclude-file=./transfer;exclude-
file=./tmp/*;exclude-file=./var/tmp/*;exclude-file=./Network/Servers/
*;exclude-file=*/*.ts;exclude-file=*/*.mpg;exclude-file=*/
*.mpeg;exclude-file=*/*.mp4;exclude-file=./proc;exclude-file=./
sys;exclude-file=./vstore;exclude-file=./home/perforce/backup/
*;exclude-file=./lon_transfer/*;exclude-file=./lon_public/*;exclude-
file=./downloads/*;exclude-file=./u01/*;
amandad: time 0.047: sending ACK pkt:
<<<<<
>>>>>
security_streaminit(stream=0x9384ee8, driver=0xb7c0c0 (krb5))
security_streaminit(stream=0x9394f10, driver=0xb7c0c0 (krb5))
security_streaminit(stream=0x93a4f38, driver=0xb7c0c0 (krb5))
amandad: time 0.066: sending REP pkt:
<<<<<
CONNECT DATA 4999 MESG 4998 INDEX 4997
OPTIONS features=fffffeff9ffeffffff7f;
>>>>>
amandad: time 0.088: received ACK pkt:
<<<<<
>>>>>
security_close(handle=0x9363f68, driver=0xb7c0c0 (krb5))
security_stream_close(0x93644d8)
security_stream_close(0x9384ee8)
security_stream_close(0x93a4f38)
security_stream_close(0x9394f10)
amandad: time 449.562: pid 13217 finish time Tue Feb 6 00:31:34 2007
and finally some extracts from amdump logfile :
driver: adjust_diskspace: time 1445.366: qtvsrv1.xxxx:/usr /backup/
amanda/dumps/20070205235902/qtvsrv1.xxxx._usr.0
driver: adjust_diskspace: time 1445.366: hdisk HD1 done, reserved
798848 used 0 diff -798848 alloc 11509355 dumpers 5
driver: adjust_diskspace: time 1445.366: after: disk qtvsrv1.xxxx:/
usr used 0
driver: find_diskspace: time 1445.367: want 9504 K
driver: find_diskspace: time 1445.367: find diskspace: size 9504 hf
45705641 df 45704937 da 9504 ha 9536
driver: find_diskspace: time 1445.367: find diskspace: selected /
backup/amanda/dumps free 45705641 reserved 9536 dumpers 5
driver: find_diskspace: time 1445.367: want 13408 K
driver: find_diskspace: time 1445.367: find diskspace: size 13408 hf
45705641 df 45704937 da 13408 ha 13440
driver: find_diskspace: time 1445.367: find diskspace: selected /
backup/amanda/dumps free 45705641 reserved 13440 dumpers 5
driver: find_diskspace: time 1445.367: want 1383808 K
driver: find_diskspace: time 1445.367: find diskspace: size 1383808
hf 45705641 df 45704937 da 1383808 ha 1383840
driver: find_diskspace: time 1445.367: find diskspace: selected /
backup/amanda/dumps free 45705641 reserved 1383840 dumpers 5
driver: find_diskspace: time 1445.367: want 1098496 K
driver: find_diskspace: time 1445.367: find diskspace: size 1098496
hf 45705641 df 45704937 da 1098496 ha 1098528
driver: find_diskspace: time 1445.367: find diskspace: selected /
backup/amanda/dumps free 45705641 reserved 1098528 dumpers 5
driver: find_diskspace: time 1445.367: want 1901536 K
driver: find_diskspace: time 1445.367: find diskspace: size 1901536
hf 45705641 df 45704937 da 1901536 ha 1901568
driver: find_diskspace: time 1445.367: find diskspace: selected /
backup/amanda/dumps free 45705641 reserved 1901568 dumpers 5
/_usr
driver: find_diskspace: time 1502.182: find diskspace: size 9504 hf
45208570 df 45207866 da 9504 ha 9536
driver: find_diskspace: time 1502.182: find diskspace: selected /
backup/amanda/dumps free 45208570 reserved 9536 dumpers 5
driver: find_diskspace: time 1502.182: want 13408 K
taper: r: Total dump size should be 1818kb, chunk size is 2097152kb
driver: find_diskspace: time 1502.182: find diskspace: size 13408 hf
45208570 df 45207866 da 13408 ha 13440
taper: r: Expecting to split into 1 parts
driver: find_diskspace: time 1502.182: find diskspace: selected /
backup/amanda/dumps free 45208570 reserved 13440 dumpers 5
driver: find_diskspace: time 1502.182: want 1383808 K
driver: find_diskspace: time 1502.182: find diskspace: size 1383808
hf 45208570 df 45207866 da 1383808 ha 1383840
driver: find_diskspace: time 1502.182: find diskspace: selected /
backup/amanda/dumps free 45208570 reserved 1383840 dumpers 5
driver: find_diskspace: time 1502.182: want 1901536 K
driver: find_diskspace: time 1502.182: find diskspace: size 1901536
hf 45208570 df 45207866 da 1901536 ha 1901568
driver: find_diskspace: time 1502.182: find diskspace: selected /
backup/amanda/dumps free 45208570 reserved 1901568 dumpers 5
driver: find_diskspace: time 1502.182: want 798816 K
driver: find_diskspace: time 1502.182: find diskspace: size 798816 hf
45208570 df 45207866 da 798816 ha 798848
driver: find_diskspace: time 1502.182: find diskspace: selected /
backup/amanda/dumps free 45208570 reserved 798848 dumpers 5
driver: assign_holdingdisk: time 1502.182: 0 assigning holding disk /
backup/amanda/dumps to disk qtvsrv1.xxxx:/usr, reserved 798848, left 0
driver: started chunker2 pid 13216
driver: send-cmd time 1502.183 to chunker2: START 20070205
chunker: pid 13216 executable chunker2 version 2.5.1p2
driver: result time 1502.197 from chunker2: PORT 37019
driver: send-cmd time 1502.197 to dumper2: PORT-DUMP 02-00027 37019
qtvsrv1.xxxx fffffeff9ffeffffff7f /usr NODEVICE 0 1970:1:1:0:0:0
GNUTAR X X X |;auth=krb5;compress-fast;index;exclude-file=./
public;exclude-file=./transfer;exclude-file=./tmp/*;exclude-file=./
var/tmp/*;exclude-file=./Network/Servers/*;exclude-file=*/
*.ts;exclude-file=*/*.mpg;exclude-file=*/*.mpeg;exclude-file=*/
*.mp4;exclude-file=./proc;exclude-file=./sys;exclude-file=./
vstore;exclude-file=./home/perforce/backup/*;exclude-file=./
lon_transfer/*;exclude-file=./lon_public/*;exclude-file=./downloads/
*;exclude-file=./u01/*;
driver: state time 1502.197 free kps: 687629 space: 44409722 taper:
writing idle-dumpers: 0 qlen tapeq: 0 runq: 4 roomq: 0 wakeup: 0
driver-idle: client-constrained
driver: interface-state time 1502.197 if default: free 87629 if
LOCAL: free 100000 if LE0: free 500000
driver: hdisk-state time 1502.197 hdisk 0: free 44409722 dumpers 6
driver: result time 1502.197 from taper: SPLIT-CONTINUE 00-00026
DailySet1-2
send request:
----
SERVICE sendbackup
OPTIONS
features=fffffeff9ffeffffff7f;hostname=qtvsrv1.xxxx;config=DailySet1;
GNUTAR /usr 0 1970:1:1:0:0:0 OPTIONS |;auth=krb5;compress-
fast;index;exclude-file=./public;exclude-file=./transfer;exclude-
file=./tmp/*;exclude-file=./var/tmp/*;exclude-file=./Network/Servers/
*;exclude-file=*/*.ts;exclude-file=*/*.mpg;exclude-file=*/
*.mpeg;exclude-file=*/*.mp4;exclude-file=./proc;exclude-file=./
sys;exclude-file=./vstore;exclude-file=./home/perforce/backup/
*;exclude-file=./lon_transfer/*;exclude-file=./lon_public/*;exclude-
file=./downloads/*;exclude-file=./u01/*;
----
got response:
----
CONNECT DATA 4999 MESG 4998 INDEX 4997
OPTIONS features=fffffeff9ffeffffff7f;
----
taper: reader-side: got label DailySet1-2 filenum 10
And finally the standard amanda log entries pertaining to the problem :
FAIL chunker qtvsrv1.xxxx /usr 20070205 0 [cannot read header: got 0
instead of 32768]
SUCCESS dumper qtvsrv1.xxxx /usr 20070205 0 [sec 449.507 kb 596774
kps 1327.6 orig-kb 1597520]
SUCCESS chunker qtvsrv1.xxxx /usr 20070205 0 [sec 450.127 kb 596774
kps 1325.9]
STATS driver estimate qtvsrv1.xxxx /usr 20070205 0 [sec 780 nkb
1597552 ckb 798816 kps 1024]
CHUNK taper qtvsrv1.xxxx /usr 20070205 1 0 [sec 16.399 kb 596832 kps
36392.4 {wr: writers 18651 rdwait 9.396 wrwait 5.189 filemark 1.650}]
CHUNKSUCCESS taper qtvsrv1.xxxx /usr 20070205 0 [sec 16.399 kb 596832
kps 36392.4 {wr: writers 18651 rdwait 9.396 wrwait 5.189 filemark
1.650}]
Phew ! Again any ideas or help appreciated !
---
AlanP
On 5 Feb 2007, at 19:29, Jean-Louis Martineau wrote:
Alan,
Could you send the amandad.<timestamps>.debug file?
You said all other client works, are they using the same amanda
version? Do they have one or more DLE?
Jean-Louis
Alan Pearson wrote:
Ok,
I've managed to get more info on this.
If I run amdump with the failing entry in the disklist on it's
own, all is fine.
If put another entry from the same machine, the other entry
backups up fine, but the second will fail.
So it sounds like some sort of timing issue ?
Here's the dumper debug which shows the problem, and remember it's
only a problem when there is more that one disklist entry for that
host.
Any help appreciated !
[EMAIL PROTECTED] OffSite]$ cat dumper.20070203130802.debug
dumper: debug 1 pid 5422 ruid 1083 euid 0: start at Sat Feb 3
13:08:02 2007
dumper: debug 1 pid 5422 ruid 1083 euid 0: rename at Sat Feb 3
13:08:02 2007
dumper: connect_port: Try port 1025: Available -
dumper: connected to 127.0.0.1.35406
dumper: our side is 0.0.0.0.1025
dumper: try_socksize: send buffer size is 65536
security_getdriver(name=krb5) returns 0xa0e0c0
security_handleinit(handle=0x8eb0a50, driver=0xa0e0c0 (krb5))
security_streaminit(stream=0x8eb3478, driver=0xa0e0c0 (krb5))
dumper: connect_port: Try port 1025: Available -
dumper: connected to 172.16.1.9.10082
dumper: our side is 0.0.0.0.1025
dumper: try_socksize: send buffer size is 65536
dumper: try_socksize: receive buffer size is 65536
security_streaminit(stream=0x8ed42f0, driver=0xa0e0c0 (krb5))
security_streaminit(stream=0x8ee4318, driver=0xa0e0c0 (krb5))
security_streaminit(stream=0x8ef4340, driver=0xa0e0c0 (krb5))
security_close(handle=0x8eb0a50, driver=0xa0e0c0 (krb5))
security_stream_close(0x8eb3478)
dumper: Building type 4 (FILE) header of size 32768 using:
dumper: Contents of *(dumpfile_t *)0x80503e0:
dumper: type = 4 (FILE)
dumper: datestamp = '20070203'
dumper: dumplevel = 0
dumper: compressed = 1
dumper: encrypted = 0
dumper: comp_suffix = '.gz'
dumper: encrypt_suffix = 'N'
dumper: name = 'qtvsrv1.xxxx'
dumper: disk = '/'
dumper: program = '/bin/gtar'
dumper: srvcompprog = ''
dumper: clntcompprog = ''
dumper: srv_encrypt = ''
dumper: clnt_encrypt = ''
dumper: recover_cmd = '/bin/gzip -dc |/bin/gtar -f - ...'
dumper: uncompress_cmd = ''
dumper: encrypt_cmd = ''
dumper: decrypt_cmd = ''
dumper: srv_decrypt_opt = ''
dumper: clnt_decrypt_opt = ''
dumper: cont_filename = ''
dumper: is_partial = 0
dumper: partnum = 0
dumper: totalparts = 0
dumper: blocksize = 32768
security_stream_close(0x8ee4318)
security_stream_close(0x8ed42f0)
security_stream_close(0x8ef4340)
dumper: connect_port: Try port 1025: Available -
dumper: connected to 127.0.0.1.35424
dumper: our side is 0.0.0.0.1025
dumper: try_socksize: send buffer size is 65536
security_getdriver(name=krb5) returns 0xa0e0c0
security_handleinit(handle=0x8eb0a50, driver=0xa0e0c0 (krb5))
security_streaminit(stream=0x8ed42f0, driver=0xa0e0c0 (krb5))
security_seterror(handle=0x8eb0a50, driver=0xa0e0c0 (krb5)
error=EOF on read from qtvsrv1.xxxx)
security_close(handle=0x8eb0a50, driver=0xa0e0c0 (krb5))
security_stream_close(0x8ed42f0)
dumper: connect_port: Try port 1025: Available -
dumper: connected to 127.0.0.1.35428
dumper: our side is 0.0.0.0.1025
dumper: try_socksize: send buffer size is 65536
security_getdriver(name=krb5) returns 0xa0e0c0
security_handleinit(handle=0x8ed4270, driver=0xa0e0c0 (krb5))
security_streaminit(stream=0x8ed42f0, driver=0xa0e0c0 (krb5))
security_stream_seterr(0x8ed42f0, krb5 write error to
qtvsrv1.xxxx: Broken pipe)
security_seterror(handle=0x8ed4270, driver=0xa0e0c0 (krb5)
error=krb5 write error to qtvsrv1.xxxx: Broken pipe)
security_seterror(handle=0x8ed4270, driver=0xa0e0c0 (krb5)
error=error sending REQ: krb5 write error to qtvsrv1.xxxx: Broken
pipe)
security_close(handle=0x8ed4270, driver=0xa0e0c0 (krb5))
security_stream_close(0x8ed42f0)
dumper: pid 5422 finish time Sat Feb 3 13:09:38 2007
---
AlanP
