> Can you send
> your whole amflush log, as well as the taper debug log?
Sure. Here is amflush.1, taper.20080609100127.debug follows:
amdump: start at Mon Jun 9 10:01:26 MDT 2008
amdump: datestamp 20080609
amdump: starttime 20080609100126
amdump: starttime-locale-independent 2008-06-09 10:01:26 MDT
planner: pid 31982 executable /usr/libexec/amanda/planner version 2.6.0p1
planner: build: VERSION="Amanda-2.6.0p1"
planner: BUILT_DATE="Tue May 13 19:36:27
PDT 2008"
planner: BUILT_MACH="i686-pc-linux-gnu"
BUILT_REV="1019"
planner: BUILT_BRANCH="amanda-260" CC="gcc"
planner: paths: bindir="/usr/bin" sbindir="/usr/sbin"
planner: libexecdir="/usr/libexec"
planner: amlibexecdir="/usr/libexec/amanda"
mandir="/usr/share/man"
planner: AMANDA_TMPDIR="/tmp/amanda"
planner: AMANDA_DBGDIR="/var/log/amanda"
CONFIG_DIR="/etc/amanda"
planner: DEV_PREFIX="/dev/" RDEV_PREFIX="/dev/r"
planner: DUMP="/sbin/dump"
RESTORE="/sbin/restore" VDUMP=UNDEF
planner: VRESTORE=UNDEF XFSDUMP=UNDEF
XFSRESTORE=UNDEF VXDUMP=UNDEF
planner: VXRESTORE=UNDEF SAMBA_CLIENT=UNDEF
GNUTAR="/bin/tar"
planner: COMPRESS_PATH="/usr/bin/gzip"
planner: UNCOMPRESS_PATH="/usr/bin/gzip"
LPRCMD="/usr/bin/lpr"
planner: MAILER="/usr/bin/Mail"
planner:
listed_incr_dir="/var/lib/amanda/gnutar-lists"
planner: defs: DEFAULT_SERVER="localhost"
DEFAULT_CONFIG="DailySet1"
planner: DEFAULT_TAPE_SERVER="localhost"
DEFAULT_TAPE_DEVICE=""
planner: HAVE_MMAP NEED_STRSTR HAVE_SYSVSHM
LOCKING=**NONE**
planner: SETPGRP_VOID ASSERTIONS
AMANDA_DEBUG_DAYS=4 BSD_SECURITY
planner: USE_AMANDAHOSTS
CLIENT_LOGIN="amandabackup" CHECK_USERID
planner: HAVE_GZIP COMPRESS_SUFFIX=".gz"
COMPRESS_FAST_OPT="--fast"
planner: COMPRESS_BEST_OPT="--best"
UNCOMPRESS_OPT="-dc"
READING CONF INFO...
driver: pid 31983 executable /usr/libexec/amanda/driver version 2.6.0p1
planner: timestamp 20080609100126
planner: time 0.000: startup took 0.000 secs
SENDING FLUSHES...
ENDFLUSH
SETTING UP FOR ESTIMATES...
planner: time 0.000: setting up estimates for 172.16.1.126:/test
172.16.1.126:/test overdue 14040 days for level 0
setup_estimate: 172.16.1.126:/test: command 0, options:
none last_level -1 next_level0 -14040 level_days 0
getting estimates 0 (-2) -1 (-2) -1 (-2)
planner: time 0.001: setting up estimates took 0.000 secs
GETTING ESTIMATES...
driver: adding holding disk 0 dir /var/dumps/Main size 190496768 chunksize
1048576
reserving 190496768 out of 190496768 for degraded-mode dumps
driver: send-cmd time 0.003 to taper: START-TAPER 20080609100126
driver: started dumper0 pid 31985
driver: send-cmd time 0.004 to dumper0: START 20080609100126
driver: started dumper1 pid 31986
driver: send-cmd time 0.006 to dumper1: START 20080609100126
driver: started dumper2 pid 31987
driver: send-cmd time 0.008 to dumper2: START 20080609100126
driver: started dumper3 pid 31988
driver: send-cmd time 0.010 to dumper3: START 20080609100126
driver: start time 0.010 inparallel 4 bandwidth 8000 diskspace
190496768 dir OBSOLETE datestamp 20080609100126 driver: drain-ends
tapeq FIRST big-dumpers sssS
dumper: pid 31985 executable dumper0 version 2.6.0p1
taper: pid 31984 executable taper version 2.6.0p1
dumper: pid 31987 executable dumper2 version 2.6.0p1
dumper: pid 31988 executable dumper3 version 2.6.0p1
dumper: pid 31986 executable dumper1 version 2.6.0p1
planner: time 0.179: got partial result for host 172.16.1.126 disk
/test: 0 -> -2K, -1 -> -2K, -1 -> -2K
planner: time 1.059: got partial result for host 172.16.1.126 disk
/test: 0 -> 2065870K, -1 -> -2K, -1 -> -2K
planner: time 1.061: got result for host 172.16.1.126 disk /test: 0
-> 2065870K, -1 -> -2K, -1 -> -2K
planner: time 1.061: getting estimates took 1.060 secs
FAILED QUEUE: empty
DONE QUEUE:
0: 172.16.1.126 /test
ANALYZING ESTIMATES...
pondering 172.16.1.126:/test... next_level0 -14040 last_level -1 (due
for level 0) (new disk, can't switch to degraded mode)
curr level 0 nsize 2065870 csize 1032935 total size 1033031 total_lev0
1032935 balanced-lev0size 258233
INITIAL SCHEDULE (size 1033031):
172.16.1.126 /test pri 14041 lev 0 nsize 2065870 csize 1032935
DELAYING DUMPS IF NEEDED, total_size 1033031, tape length 209715200 mark 0
delay: Total size now 1033031.
PROMOTING DUMPS IF NEEDED, total_lev0 1032935, balanced_size 258233...
planner: time 1.061: analysis took 0.000 secs
GENERATING SCHEDULE:
--------
DUMP 172.16.1.126 ffffffff9ffeffffffff00 /test 20080609100126 14041 0
1970:1:1:0:0:0 2065870 1032935 1008 1024
--------
taper: using label `CamMain-04' date `20080609100126'
driver: result time 1.557 from taper: TAPER-OK
driver: state time 1.558 free kps: 8000 space: 190496768 taper:
idle idle-dumpers: 4 qlen tapeq: 0 runq: 0 roomq: 0 wakeup:
0 driver-idle: not-idle
driver: interface-state time 1.558 if default: free 8000
driver: hdisk-state time 1.558 hdisk 0: free 190496768 dumpers 0
driver: flush size 0
driver: started chunker0 pid 32743
driver: send-cmd time 1.558 to chunker0: START 20080609100126
driver: send-cmd time 1.559 to chunker0: PORT-WRITE 00-00001
/var/dumps/Main/20080609100126/172.16.1.126._test.0 172.16.1.126
ffffffff9ffeffffffff00 /test 0 1970:1:1:0:0:0 1048576
GNUTAR 1033024 |;auth=bsdtcp;srvcomp-fast;index;
chunker: pid 32743 executable chunker0 version 2.6.0p1
driver: result time 1.578 from chunker0: PORT 11002
driver: send-cmd time 1.578 to dumper0: PORT-DUMP 00-00001 11002
172.16.1.126 ffffffff9ffeffffffff00 /test NODEVICE 0
1970:1:1:0:0:0 GNUTAR X X X
|;auth=bsdtcp;srvcomp-fast;index;
driver: state time 172.837 free kps: 6976 space: 189463744
taper: idle idle-dumpers: 3 qlen tapeq: 0 runq: 0 roomq: 0
wakeup: 0 driver-idle: no-dumpers
driver: interface-state time 172.837 if default: free 6976
driver: hdisk-state time 172.837 hdisk 0: free 189463744 dumpers 1
driver: result time 172.837 from chunker0: RQ-MORE-DISK 00-00001
driver: send-cmd time 172.837 to chunker0: CONTINUE 00-00001
/var/dumps/Main/20080609100126/172.16.1.126._test.0 1048576 51680
driver: state time 181.954 free kps: 6976 space: 189412064
taper: idle idle-dumpers: 3 qlen tapeq: 0 runq: 0 roomq: 0
wakeup: 0 driver-idle: no-dumpers
driver: interface-state time 181.954 if default: free 6976
driver: hdisk-state time 181.954 hdisk 0: free 189412064 dumpers 1
driver: result time 181.954 from chunker0: RQ-MORE-DISK 00-00001
driver: send-cmd time 181.954 to chunker0: CONTINUE 00-00001
/var/dumps/Main/20080609100126/172.16.1.126._test.0 1048576 54272
driver: state time 194.542 free kps: 6976 space: 189357792
taper: idle idle-dumpers: 3 qlen tapeq: 0 runq: 0 roomq: 0
wakeup: 0 driver-idle: no-dumpers
driver: interface-state time 194.542 if default: free 6976
driver: hdisk-state time 194.542 hdisk 0: free 189357792 dumpers 1
driver: result time 194.542 from chunker0: RQ-MORE-DISK 00-00001
driver: send-cmd time 194.542 to chunker0: CONTINUE 00-00001
/var/dumps/Main/20080609100126/172.16.1.126._test.0 1048576 56992
driver: state time 216.384 free kps: 6976 space: 189300800
taper: idle idle-dumpers: 3 qlen tapeq: 0 runq: 0 roomq: 0
wakeup: 0 driver-idle: no-dumpers
driver: interface-state time 216.384 if default: free 6976
driver: hdisk-state time 216.384 hdisk 0: free 189300800 dumpers 1
driver: result time 216.384 from chunker0: RQ-MORE-DISK 00-00001
driver: send-cmd time 216.384 to chunker0: CONTINUE 00-00001
/var/dumps/Main/20080609100126/172.16.1.126._test.0 1048576 59840
driver: state time 216.829 free kps: 6976 space: 189240960
taper: idle idle-dumpers: 3 qlen tapeq: 0 runq: 0 roomq: 0
wakeup: 0 driver-idle: no-dumpers
driver: interface-state time 216.829 if default: free 6976
driver: hdisk-state time 216.829 hdisk 0: free 189240960 dumpers 1
driver: result time 216.829 from dumper0: DONE 00-00001 2065870 2065870
209 "[sec 209.099 kb 2065870 kps 9879.9 orig-kb 2065870]"
driver: finished-cmd time 216.829 dumper0 dumped 172.16.1.126:/test
driver: send-cmd time 216.829 to chunker0: DONE 00-00001
driver: state time 216.830 free kps: 6976 space: 189240960
taper: idle idle-dumpers: 3 qlen tapeq: 0 runq: 0 roomq: 0
wakeup: 0 driver-idle: no-dumpers
driver: interface-state time 216.830 if default: free 6976
driver: hdisk-state time 216.830 hdisk 0: free 189240960 dumpers 1
driver: result time 216.830 from chunker0: DONE 00-00001 1196235
"[sec 215.232 kb 1196235 kps 5558.2]"
driver: finished-cmd time 216.830 chunker0 chunked 172.16.1.126:/test
driver: send-cmd time 216.832 to taper: FILE-WRITE 00-00002
/var/dumps/Main/20080609100126/172.16.1.126._test.0 172.16.1.126 /test 0
20080609100126 21474836480
driver: startaflush: FIRST 172.16.1.126 /test 1196299 204472320
taper: Total dump size should be 1196235kb, part size is 21474836480kb
driver: state time 216.833 free kps: 8000 space: 189300469
taper: writing idle-dumpers: 4 qlen tapeq: 0 runq: 0 roomq:
0 wakeup: 0 driver-idle: no-dumpers
driver: interface-state time 216.833 if default: free 8000
driver: hdisk-state time 216.833 hdisk 0: free 189300469 dumpers 0
driver: result time 216.833 from taper: REQUEST-NEW-TAPE 00-00002
driver: send-cmd time 216.833 to taper: NO-NEW-TAPE
driver: state time 216.833 free kps: 8000 space: 189300469
taper: writing idle-dumpers: 4 qlen tapeq: 0 runq: 0 roomq:
0 wakeup: 0 driver-idle: no-dumpers
driver: interface-state time 216.833 if default: free 8000
driver: hdisk-state time 216.833 hdisk 0: free 189300469 dumpers 0
driver: result time 216.833 from taper: FAILED 00-00002 INPUT-GOOD
TAPE-ERROR "" "No new tape."
driver: finished-cmd time 216.833 taper wrote 172.16.1.126:/test
driver: taper will retry 172.16.1.126 /test
driver: send-cmd time 216.833 to taper: FILE-WRITE 00-00003
/var/dumps/Main/20080609100126/172.16.1.126._test.0 172.16.1.126 /test 0
20080609100126 21474836480
driver: startaflush: FIRST 172.16.1.126 /test 1196299 203276021
taper: Total dump size should be 1196235kb, part size is 21474836480kb
driver: state time 216.834 free kps: 8000 space: 189300469
taper: writing idle-dumpers: 4 qlen tapeq: 0 runq: 0 roomq:
0 wakeup: 0 driver-idle: no-dumpers
driver: interface-state time 216.834 if default: free 8000
driver: hdisk-state time 216.834 hdisk 0: free 189300469 dumpers 0
driver: result time 216.834 from taper: REQUEST-NEW-TAPE 00-00003
driver: send-cmd time 216.834 to taper: NO-NEW-TAPE
driver: state time 216.834 free kps: 8000 space: 189300469
taper: writing idle-dumpers: 4 qlen tapeq: 0 runq: 0 roomq:
0 wakeup: 0 driver-idle: no-dumpers
driver: interface-state time 216.834 if default: free 8000
driver: hdisk-state time 216.834 hdisk 0: free 189300469 dumpers 0
driver: result time 216.834 from taper: FAILED 00-00003 INPUT-GOOD
TAPE-ERROR "" "No new tape."
driver: finished-cmd time 216.834 taper wrote 172.16.1.126:/test
driver: taper failed 172.16.1.126 /test, too many taper retry
driver: state time 216.834 free kps: 8000 space: 189300469
taper: idle idle-dumpers: 4 qlen tapeq: 0 runq: 0 roomq: 0
wakeup: 0 driver-idle: no-dumpers
driver: interface-state time 216.834 if default: free 8000
driver: hdisk-state time 216.834 hdisk 0: free 189300469 dumpers 0
driver: QUITTING time 216.834 telling children to quit
driver: send-cmd time 216.834 to dumper0: QUIT
driver: send-cmd time 216.834 to dumper1: QUIT
driver: send-cmd time 216.835 to dumper2: QUIT
driver: send-cmd time 216.835 to dumper3: QUIT
driver: send-cmd time 216.835 to taper: QUIT
taper: DONE
driver: FINISHED time 217.837
amdump: end at Mon Jun 9 10:05:04 MDT 2008
Here is taper.20080609100127.debug
1213027287.002948: taper: pid 31984 ruid 500 euid 500: start at Mon
Jun 9 10:01:27 2008
1213027287.009233: taper: taper: pid 31984 executable taper version
2.6.0p1
1213027287.011095: taper: pid 31984 ruid 500 euid 500: rename at
Mon Jun 9 10:01:27 2008
1213027287.011348: taper: getcmd: START-TAPER 20080609100126
1213027287.393321: taper: changer_query: changer return was 7 1 1
1213027287.393400: taper: changer_query: searchable = 1
1213027287.393416: taper: changer_find: looking for NULL changer is
searchable = 1
1213027287.801157: taper: changer_label: CamMain-04 for slot 4
1213027288.180230: taper: changer_query: changer return was 7 1 1
1213027288.180291: taper: changer_query: searchable = 1
1213027288.180306: taper: changer_label: calling changer -label
CamMain-04
1213027288.550402: taper: putresult: 25 TAPER-OK
1213027503.825114: taper: getcmd: FILE-WRITE 00-00002
/var/dumps/Main/20080609100126/172.16.1.126._test.0 172.16.1.126 /test 0
20080609100126 21474836480
1213027503.825717: taper: putresult: 26 REQUEST-NEW-TAPE
1213027503.825979: taper: getcmd: NO-NEW-TAPE
1213027503.826047: taper: putresult: 10 FAILED
1213027503.826396: taper: getcmd: FILE-WRITE 00-00003
/var/dumps/Main/20080609100126/172.16.1.126._test.0 172.16.1.126 /test 0
20080609100126 21474836480
1213027503.826755: taper: putresult: 26 REQUEST-NEW-TAPE
1213027503.826995: taper: getcmd: NO-NEW-TAPE
1213027503.827047: taper: putresult: 10 FAILED
1213027503.827771: taper: getcmd: QUIT
1213027503.827798: taper: putresult: 2 QUITTIN
+----------------------------------------------------------------------
|This was sent by nbarss AT cambric DOT com via Backup Central.
|Forward SPAM to abuse AT backupcentral DOT com.
+----------------------------------------------------------------------
|
