Amanda-Users

Re: client failure

2009-04-09 17:30:18
Subject: Re: client failure
From: Brian Cuttler <brian AT wadsworth DOT org>
To: "Dustin J. Mitchell" <dustin AT zmanda DOT com>, martineau AT zmanda DOT com
Date: Thu, 9 Apr 2009 16:55:15 -0400
Dustin,
Jean-Louis,

On Thu, Apr 09, 2009 at 04:37:24PM -0400, Dustin J. Mitchell wrote:
> On Thu, Apr 9, 2009 at 4:21 PM, Brian Cuttler <brian AT wadsworth DOT org> 
> wrote:
> > ? everest /images3 lev 0 ?FAILED [dumper1 died]
> 
> Check the dumper debug logs on the server, rather than the client.




# more chunker.20090409164847.debug 

1239310127.748174: chunker: pid 23052 ruid 110 euid 110 version 2.6.1: start at 
Thu Apr  9 16:48:47 2009
1239310127.751130: chunker: pid 23052 ruid 110 euid 110 version 2.6.1: rename at
 Thu Apr  9 16:48:47 2009
1239310127.751381: chunker: getcmd: START 20090409164827
1239310127.751428: chunker: getcmd: PORT-WRITE 00-00003 /thump/amanda/work/20090
409164827/everest._images3.0 everest 34cbfe811f010000000000 /images3 0 1970:1:1:
0:0:0 1048576 DUMP 1178784 |;bsd-auth;compress-fast;index;
1239310127.752279: chunker: stream_server opening socket with family 2 (requeste
d family was 2)
1239310127.752350: chunker: try_socksize: receive buffer size is 65536
1239310127.758397: chunker: bind_portrange2: Try  port 10096: Available - Succes
s
1239310127.758476: chunker: stream_server: waiting for connection: 0.0.0.0.10096
1239310127.758491: chunker: putresult: 23 PORT
1239310127.764993: chunker: stream_accept: connection from 127.0.0.1.10084
1239310127.765019: chunker: try_socksize: receive buffer size is 65536
1239310127.765485: chunker: putresult: 10 FAILED
1239310127.765592: chunker: pid 23052 finish time Thu Apr  9 16:48:47 2009



amdump.1
========

amdump: start at Thu Apr 9 16:48:27 EDT 2009
amdump: datestamp 20090409
amdump: starttime 20090409164827
amdump: starttime-locale-independent 2009-04-09 16:48:27 EDT
planner: pid 22319 executable /usr/local/libexec/amanda/planner version 
2.6.1-20090227
planner: build: VERSION="Amanda-2.6.1-20090227"
planner:        BUILT_DATE="Mon Mar 9 17:02:49 EDT 2009"
planner:        BUILT_MACH="i386-pc-solaris2.10" BUILT_REV="1714"
planner:        BUILT_BRANCH="amanda-261" CC="/opt/SUNWspro/bin/cc"
planner: paths: bindir="/usr/local/bin" sbindir="/usr/local/sbin"
planner:        libexecdir="/usr/local/libexec"
planner:        amlibexecdir="/usr/local/libexec/amanda"
planner:        mandir="/usr/local/share/man" AMANDA_TMPDIR="/tmp/amanda"
planner:        AMANDA_DBGDIR="/tmp/amanda"
planner:        CONFIG_DIR="/usr/local/etc/amanda" DEV_PREFIX="/dev/dsk/"
planner:        RDEV_PREFIX="/dev/rdsk/" DUMP="/usr/sbin/ufsdump"
planner:        RESTORE="/usr/sbin/ufsrestore" VDUMP=UNDEF VRESTORE=UNDEF
planner:        XFSDUMP=UNDEF XFSRESTORE=UNDEF VXDUMP=UNDEF VXRESTORE=UNDEF
planner:        SAMBA_CLIENT="/usr/sfw/bin/smbclient"
planner:        GNUTAR="/usr/sfw/bin/gtar" COMPRESS_PATH="/usr/bin/gzip"
planner:        UNCOMPRESS_PATH="/usr/bin/gzip" LPRCMD="/usr/bin/lpr"
planner:         MAILER=UNDEF
planner:        listed_incr_dir="/usr/local/var/amanda/gnutar-lists"
planner: defs:  DEFAULT_SERVER="curie" DEFAULT_CONFIG="DailySet1"
planner:        DEFAULT_TAPE_SERVER="curie" DEFAULT_TAPE_DEVICE=""
planner:        HAVE_MMAP NEED_STRSTR HAVE_SYSVSHM AMFLOCK_POSIX AMFLOCK_LOCKF
planner:        AMFLOCK_LNLOCK SETPGRP_VOID AMANDA_DEBUG_DAYS=4 BSD_SECURITY
planner:        USE_AMANDAHOSTS CLIENT_LOGIN="amanda" CHECK_USERID HAVE_GZIP
planner:        COMPRESS_SUFFIX=".gz" COMPRESS_FAST_OPT="--fast"
planner:        COMPRESS_BEST_OPT="--best" UNCOMPRESS_OPT="-dc"
READING CONF INFO...
driver: pid 22320 executable /usr/local/libexec/amanda/driver version 
2.6.1-20090227
planner: timestamp 20090409164827
planner: time 0.000: startup took 0.000 secs

SENDING FLUSHES...
driver: tape size 822083584
driver: adding holding disk 0 dir /amanda0/work size 469420032 chunksize 1048576
driver: adding holding disk 1 dir /thump/amanda/work size 9148094464 chunksize 
1048576
reserving 0 out of 9617514496 for degraded-mode dumps
driver: send-cmd time 0.004 to taper: START-TAPER 20090409164827
FLUSH trel /trel 20090409133424 1 /thump/amanda/work/20090409133424/trel._trel.1
ENDFLUSH

SETTING UP FOR ESTIMATES...
planner: time 0.002: setting up estimates for everest:/images3
everest:/images3 overdue 14344 days for level 0
setup_estimate: everest:/images3: command 0, options: none    last_level -1 
next_level0 -14344 level_days 0    getting estimates 0 (-2) -1 (-2) -1 (-2)
planner: time 0.002: setting up estimates took 0.000 secs

GETTING ESTIMATES...
driver: started dumper0 pid 22322
driver: send-cmd time 0.005 to dumper0: START 20090409164827
driver: started dumper1 pid 22323
driver: send-cmd time 0.006 to dumper1: START 20090409164827
driver: started dumper2 pid 22324
driver: send-cmd time 0.006 to dumper2: START 20090409164827
driver: started dumper3 pid 22325
driver: send-cmd time 0.007 to dumper3: START 20090409164827
driver: start time 0.007 inparallel 4 bandwidth 8000000 diskspace 9617514496  
dir OBSOLETE datestamp 20090409164827 driver: drain-ends tapeq FIRST 
big-dumpers ssSS
dumper: pid 22322 executable dumper0 version 2.6.1-20090227
dumper: pid 22323 executable dumper1 version 2.6.1-20090227
dumper: pid 22324 executable dumper2 version 2.6.1-20090227
taper: pid 22321 executable taper version 2.6.1-20090227
dumper: pid 22325 executable dumper3 version 2.6.1-20090227
planner: time 1.871: got result for host everest disk /images3: 0 -> 2357352K, 
-1 -> -2K, -1 -> -2K
planner: time 1.871: getting estimates took 1.869 secs
FAILED QUEUE: empty
DONE QUEUE:
  0: everest    /images3

ANALYZING ESTIMATES...
pondering everest:/images3... next_level0 -14344 last_level -1 (due for level 
0) (new disk, can't switch to degraded mode)
  curr level 0 nsize 2357352 csize 1178676 total size 1178772 total_lev0 
1178676 balanced-lev0size 235735
INITIAL SCHEDULE (size 1178772):
  everest /images3 pri 14345 lev 0 nsize 2357352 csize 1178676

DELAYING DUMPS IF NEEDED, total_size 1178772, tape length 1644167168 mark 0
  delay: Total size now 1178772.

PROMOTING DUMPS IF NEEDED, total_lev0 1178676, balanced_size 235735...
planner: time 1.872: analysis took 0.000 secs

GENERATING SCHEDULE:
--------
DUMP everest 34cbfe811f010000000000 /images3 20090409164827 14345 0 
1970:1:1:0:0:0 2357352 1178676 1151 1024 "Can't switch to degraded mode when 
using a new disk"
--------
taper: using label `Curie18' date `20090409164827'
driver: result time 4.654 from taper: TAPER-OK 
driver: send-cmd time 4.655 to taper: FILE-WRITE 00-00001 
/thump/amanda/work/20090409133424/trel._trel.1 trel /trel 1 20090409133424 0
driver: startaflush: FIRST trel /trel 62972 822083584
driver: state time 4.655 free kps: 8000000 space: 9617514496 taper: writing 
idle-dumpers: 4 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 0 driver-idle: not-idle
driver: interface-state time 4.655 if default: free 8000000
driver: hdisk-state time 4.655 hdisk 0: free 469420032 dumpers 0 hdisk 1: free 
9148094464 dumpers 0
driver: state time 4.655 free kps: 8000000 space: 9617514496 taper: writing 
idle-dumpers: 4 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 0 driver-idle: not-idle
driver: interface-state time 4.655 if default: free 8000000
driver: hdisk-state time 4.655 hdisk 0: free 469420032 dumpers 0 hdisk 1: free 
9148094464 dumpers 0
driver: flush size 0
driver: started chunker0 pid 22878
driver: send-cmd time 4.655 to chunker0: START 20090409164827
driver: send-cmd time 4.656 to chunker0: PORT-WRITE 01-00002 
/thump/amanda/work/20090409164827/everest._images3.0 everest 
34cbfe811f010000000000 /images3 0 1970:1:1:0:0:0 1048576 DUMP 1178784 
|;bsd-auth;compress-fast;index;
chunker: pid 22878 executable chunker0 version 2.6.1-20090227
driver: result time 4.679 from chunker0: PORT 10094
driver: send-cmd time 4.679 to dumper0: PORT-DUMP 01-00002 10094 everest 
34cbfe811f010000000000 /images3 NODEVICE 0 1970:1:1:0:0:0 DUMP X X X bsd 
|;bsd-auth;compress-fast;index;
driver: state time 4.679 free kps: 7998976 space: 9616335712 taper: writing 
idle-dumpers: 3 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 0 driver-idle: no-dumpers
driver: interface-state time 4.679 if default: free 7998976
driver: hdisk-state time 4.679 hdisk 0: free 469420032 dumpers 0 hdisk 1: free 
9146915680 dumpers 1
driver: state time 4.679 free kps: 7998976 space: 9616335712 taper: writing 
idle-dumpers: 3 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 0 driver-idle: no-dumpers
driver: interface-state time 4.679 if default: free 7998976
driver: hdisk-state time 4.679 hdisk 0: free 469420032 dumpers 0 hdisk 1: free 
9146915680 dumpers 1
driver: result time 4.679 from taper: REQUEST-NEW-TAPE 00-00001
driver: send-cmd time 4.679 to taper: NEW-TAPE
driver: state time 4.685 free kps: 7998976 space: 9616335712 taper: writing 
idle-dumpers: 3 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 0 driver-idle: no-dumpers
driver: interface-state time 4.685 if default: free 7998976
driver: hdisk-state time 4.685 hdisk 0: free 469420032 dumpers 0 hdisk 1: free 
9146915680 dumpers 1
driver: result time 4.685 from dumper0: (eof)
driver: send-cmd time 4.686 to chunker0: FAILED 01-00002
driver: state time 4.686 free kps: 7998976 space: 9616335712 taper: writing 
idle-dumpers: 4 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 0 driver-idle: no-dumpers
driver: interface-state time 4.686 if default: free 7998976
driver: hdisk-state time 4.686 hdisk 0: free 469420032 dumpers 0 hdisk 1: free 
9146915680 dumpers 1
driver: result time 4.686 from chunker0: FAILED 01-00002 "[cannot read header: 
got 0 bytes instead of 32768]"
driver: state time 10.534 free kps: 8000000 space: 9617514496 taper: writing 
idle-dumpers: 4 qlen tapeq: 0 runq: 1 roomq: 0 wakeup: 15 driver-idle: 
start-wait
driver: interface-state time 10.534 if default: free 8000000
driver: hdisk-state time 10.534 hdisk 0: free 469420032 dumpers 0 hdisk 1: free 
9148094464 dumpers 0
driver: result time 10.534 from taper: NEW-TAPE 00-00001 Curie18
driver: state time 18.273 free kps: 8000000 space: 9617514496 taper: writing 
idle-dumpers: 4 qlen tapeq: 0 runq: 1 roomq: 0 wakeup: 15 driver-idle: 
start-wait
driver: interface-state time 18.273 if default: free 8000000
driver: hdisk-state time 18.273 hdisk 0: free 469420032 dumpers 0 hdisk 1: free 
9148094464 dumpers 0
driver: result time 18.273 from taper: PARTDONE 00-00001 Curie18 1 62940 "[sec 
4.946400 kb 62940 kps 12724.405628]"
driver: state time 18.273 free kps: 8000000 space: 9617514496 taper: writing 
idle-dumpers: 4 qlen tapeq: 0 runq: 1 roomq: 0 wakeup: 15 driver-idle: 
start-wait
driver: interface-state time 18.273 if default: free 8000000
driver: hdisk-state time 18.273 hdisk 0: free 469420032 dumpers 0 hdisk 1: free 
9148094464 dumpers 0
driver: result time 18.273 from taper: DONE 00-00001 INPUT-GOOD TAPE-GOOD "[sec 
4.946400 kb 62940 kps 12724.405628]" "" ""
driver: finished-cmd time 18.273 taper wrote trel:/trel
driver: started chunker1 pid 23052
driver: send-cmd time 20.284 to chunker1: START 20090409164827
driver: send-cmd time 20.285 to chunker1: PORT-WRITE 00-00003 
/thump/amanda/work/20090409164827/everest._images3.0 everest 
34cbfe811f010000000000 /images3 0 1970:1:1:0:0:0 1048576 DUMP 1178784 
|;bsd-auth;compress-fast;index;
chunker: pid 23052 executable chunker1 version 2.6.1-20090227
driver: result time 20.308 from chunker1: PORT 10096
driver: send-cmd time 20.308 to dumper1: PORT-DUMP 00-00003 10096 everest 
34cbfe811f010000000000 /images3 NODEVICE 0 1970:1:1:0:0:0 DUMP X X X bsd 
|;bsd-auth;compress-fast;index;
driver: state time 20.308 free kps: 7998976 space: 9616398684 taper: idle 
idle-dumpers: 3 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 0 driver-idle: no-dumpers
driver: interface-state time 20.308 if default: free 7998976
driver: hdisk-state time 20.308 hdisk 0: free 469420032 dumpers 0 hdisk 1: free 
9146978652 dumpers 1
driver: state time 20.315 free kps: 7998976 space: 9616398684 taper: idle 
idle-dumpers: 3 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 0 driver-idle: no-dumpers
driver: interface-state time 20.315 if default: free 7998976
driver: hdisk-state time 20.315 hdisk 0: free 469420032 dumpers 0 hdisk 1: free 
9146978652 dumpers 1
driver: result time 20.315 from dumper1: (eof)
driver: send-cmd time 20.315 to chunker1: FAILED 00-00003
driver: state time 20.315 free kps: 7998976 space: 9616398684 taper: idle 
idle-dumpers: 4 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 0 driver-idle: no-dumpers
driver: interface-state time 20.315 if default: free 7998976
driver: hdisk-state time 20.315 hdisk 0: free 469420032 dumpers 0 hdisk 1: free 
9146978652 dumpers 1
driver: result time 20.315 from chunker1: FAILED 00-00003 "[cannot read header: 
got 0 bytes instead of 32768]"
driver: state time 20.317 free kps: 8000000 space: 9617577468 taper: idle 
idle-dumpers: 4 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 0 driver-idle: no-dumpers
driver: interface-state time 20.317 if default: free 8000000
driver: hdisk-state time 20.317 hdisk 0: free 469420032 dumpers 0 hdisk 1: free 
9148157436 dumpers 0
driver: QUITTING time 20.317 telling children to quit
driver: send-cmd time 20.317 to dumper2: QUIT ""
driver: send-cmd time 20.318 to dumper3: QUIT ""
driver: send-cmd time 20.318 to taper: QUIT
driver: dumper1 pid 22323 exited with signal 11
taper: DONE
driver: dumper0 pid 22322 exited with signal 11
driver: FINISHED time 25.365
amdump: end at Thu Apr  9 16:48:52 EDT 2009


---
   Brian R Cuttler                 brian.cuttler AT wadsworth DOT org
   Computer Systems Support        (v) 518 486-1697
   Wadsworth Center                (f) 518 473-6384
   NYS Department of Health        Help Desk 518 473-0773



IMPORTANT NOTICE: This e-mail and any attachments may contain
confidential or sensitive information which is, or may be, legally
privileged or otherwise protected by law from further disclosure.  It
is intended only for the addressee.  If you received this in error or
from someone who was not authorized to send it to you, please do not
distribute, copy or use it or any attachments.  Please notify the
sender immediately by reply e-mail and delete this from your
system. Thank you for your cooperation.



<Prev in Thread] Current Thread [Next in Thread>