(Reposting.)
The follwing is with Amanda 2.5.0 (Debian package 1:2.5.0-2); Amanda
has no free tape in access (degraded mode), so the dump should go to
holdingdisk and stay there.
When I start the dump, amstatus shows:
Using /var/log/amanda/WeeklySet1/amdump from Thu May 4 17:46:01 CEST 2006
unixserver:/data/backup 0 192436m dumping 39690m ( 20.63%) (17:53:51)
SUMMARY part real estimated
size size
partition : 1
estimated : 1 192436m
flush : 0 0m
failed : 0 0m ( 0.00%)
wait for dumping: 0 0m ( 0.00%)
dumping to tape : 0 0m ( 0.00%)
dumping : 1 39690m 192436m ( 20.63%) ( 20.63%)
dumped : 0 0m 0m ( 0.00%) ( 0.00%)
wait for writing: 0 0m 0m ( 0.00%) ( 0.00%)
wait to flush : 0 0m 0m (100.00%) ( 0.00%)
writing to tape : 0 0m 0m ( 0.00%) ( 0.00%)
failed to tape : 0 0m 0m ( 0.00%) ( 0.00%)
taped : 0 0m 0m ( 0.00%) ( 0.00%)
12 dumpers idle : not-idle
taper idle
network free kps: 44000
holding space : 1841161m (100.00%)
dumper0 busy : 0:00:00 ( 0.00%)
0 dumpers busy : 0:00:00 ( 0.00%)
1 dumper busy : 0:00:00 ( 0.00%)
A minor surpise: It says that 100% holding space is still available
even though a dump to holdingdisk already runs.
Some hours later the dump fails. amstatus shows:
Using /var/log/amanda/WeeklySet1/amdump.1 from Thu May 4 17:46:01 CEST 2006
unixserver:/data/backup 0 192436m dumping 202058m (105.00%) (17:53:51)
(waiting for holding disk space)
SUMMARY part real estimated
size size
partition : 1
estimated : 1 192436m
flush : 0 0m
failed : 0 0m ( 0.00%)
wait for dumping: 0 0m ( 0.00%)
dumping to tape : 0 0m ( 0.00%)
dumping : 1 202058m 192436m (105.00%) (105.00%)
dumped : 0 0m 0m ( 0.00%) ( 0.00%)
wait for writing: 0 0m 0m ( 0.00%) ( 0.00%)
wait to flush : 0 0m 0m (100.00%) ( 0.00%)
writing to tape : 0 0m 0m ( 0.00%) ( 0.00%)
failed to tape : 0 0m 0m ( 0.00%) ( 0.00%)
taped : 0 0m 0m ( 0.00%) ( 0.00%)
11 dumpers idle : no-dumpers
taper idle
network free kps: 35858
holding space : 1639097m ( 89.03%)
dumper0 busy : 8:30:45 ( 98.49%)
0 dumpers busy : 8:07:52 ( 94.07%) not-idle: 8:07:52 (100.00%)
1 dumper busy : 0:22:52 ( 4.41%) no-dumpers: 0:22:52 (100.00%)
Obviously there is still enough holdingdisk space.
So I looked into /var/log/amanda/WeeklySet1/amdump.1 (I quote some
parts here; the complete file is appended below.):
driver: result time 31115.937 from chunker0: RQ-MORE-DISK 00-00001
find diskspace: not enough diskspace. Left with 2412180312 K
find diskspace: not enough diskspace. Left with 2412180312 K
driver: Don't know how to send ABORT command to chunker
chunker: error [bad command after RQ-MORE-DISK: "QUIT"]
chunker: time 30645.022: error [bad command after RQ-MORE-DISK: "QUIT"]
chunker: time 30645.022: pid 7453 finish time Fri May 5 02:24:37 2006
taper: DONE [idle wait: 30645.029 secs]
I have no idea how the number 2412180312 K was calculated. It is more
than the size of all holdingdisks (see amstatus above, this number
seems to be correct).
Right now the workaround seems to be to split the DLE, my
second-largest DLE is below 180 GB and didn't cause such trouble.
Another observation: In this case the estimate is too low; above QUIT
occured after some successful RQ-MORE-DISK. So another workaround
might be to avoid RQ-MORE-DISK by setting a larger comprate.
Sven
The amdump.1 file:
amdump: start at Thu May 4 17:46:01 CEST 2006
amdump: datestamp 20060504
planner: pid 4960 executable /usr/lib/amanda/planner version 2.5.0
planner: build: VERSION="Amanda-2.5.0"
planner: BUILT_DATE="Mon Apr 3 05:06:49 PDT 2006"
planner: BUILT_MACH="Linux rover 2.6.15-15-686 #1 SMP PREEMPT Mon Feb 6
18:34:45 UTC 2006 i686 GNU/Linux"
driver: pid 4961 executable /usr/lib/amanda/driver version 2.5.0
driver: tape size 311296000
planner: CC="gcc"
planner: CONFIGURE_COMMAND="'./configure' '--prefix=/usr'
'--bindir=/usr/sbin' '--mandir=/usr/share/man' '--libexecdir=/usr/lib/amanda'
'--enable-shared' '--sysconfdir=/etc' '--localstatedir=/var/lib'
'--with-gnutar-listdir=/var/lib/amanda/gnutar-lists'
'--with-index-server=localhost' '--with-user=backup' '--with-group=backup'
'--with-bsd-security' '--with-amandahosts'
'--with-smbclient=/usr/bin/smbclient' '--with-debugging=/var/log/amanda'
'--with-dumperdir=/usr/lib/amanda/dumper.d' '--with-tcpportrange=50000,50100'
'--with-udpportrange=840,860' '--with-maxtapeblocksize=256' '--no-create'
'--no-recursion'"
planner: paths: bindir="/usr/sbin" sbindir="/usr/sbin"
planner: libexecdir="/usr/lib/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/" DUMP="/sbin/dump"
planner: RESTORE="/sbin/restore" VDUMP=UNDEF VRESTORE=UNDEF
planner: XFSDUMP="/sbin/xfsdump" XFSRESTORE="/sbin/xfsrestore"
planner: VXDUMP=UNDEF VXRESTORE=UNDEF
planner: SAMBA_CLIENT="/usr/bin/smbclient" GNUTAR="/bin/tar"
planner: COMPRESS_PATH="/bin/gzip" UNCOMPRESS_PATH="/bin/gzip"
planner: LPRCMD="/usr/bin/lpr" 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"
planner: DEFAULT_TAPE_DEVICE="null:" HAVE_MMAP HAVE_SYSVSHM
planner: LOCKING=POSIX_FCNTL SETPGRP_VOID DEBUG_CODE
planner: AMANDA_DEBUG_DAYS=4 BSD_SECURITY RSH_SECURITY USE_AMANDAHOSTS
planner: CLIENT_LOGIN="backup" FORCE_USERID HAVE_GZIP
planner: COMPRESS_SUFFIX=".gz" COMPRESS_FAST_OPT="--fast"
planner: COMPRESS_BEST_OPT="--best" UNCOMPRESS_OPT="-dc"
driver: send-cmd time 0.002 to taper: START-TAPER 20060504
READING CONF FILES...
taper: pid 4962 executable taper version 2.5.0
driver: adding holding disk 0 dir /var/spool/amanda/9/9 size 550800356
chunksize 1048576
driver: adding holding disk 1 dir /var/spool/amanda/8/8 size 138585904
chunksize 1048576
taper: page size is 4096
taper: buffer size is 32768
driver: adding holding disk 2 dir /var/spool/amanda/6/6 size 65610248 chunksize
1048576
taper: buffer[00] at 0xb7c88000
taper: buffer[01] at 0xb7c90000
taper: buffer[02] at 0xb7c98000
taper: buffer[03] at 0xb7ca0000
taper: buffer[04] at 0xb7ca8000
taper: buffer[05] at 0xb7cb0000
taper: buffer[06] at 0xb7cb8000
taper: buffer[07] at 0xb7cc0000
taper: buffer[08] at 0xb7cc8000
taper: buffer[09] at 0xb7cd0000
taper: buffer[10] at 0xb7cd8000
taper: buffer[11] at 0xb7ce0000
taper: buffer[12] at 0xb7ce8000
taper: buffer[13] at 0xb7cf0000
taper: buffer[14] at 0xb7cf8000
taper: buffer[15] at 0xb7d00000
taper: buffer[16] at 0xb7d08000
taper: buffer[17] at 0xb7d10000
taper: buffer[18] at 0xb7d18000
taper: buffer[19] at 0xb7d20000
taper: buffer structures at 0xb7d28000 for 240 bytes
driver: adding holding disk 3 dir /var/spool/amanda/5/5 size 564966916
chunksize 1048576
driver: adding holding disk 4 dir /var/spool/amanda/4/4 size 138500524
chunksize 1048576
driver: adding holding disk 5 dir /var/spool/amanda/3/3 size 289936068
chunksize 1048576
planner: time 0.012: startup took 0.012 secs
SENDING FLUSHES...
ENDFLUSH
SETTING UP FOR ESTIMATES...
planner: time 0.012: setting up estimates for unixserver:/data/backup
driver: adding holding disk 6 dir /var/spool/amanda/2/2 size 125241712
chunksize 1048576
driver: adding holding disk 7 dir /var/spool/amanda/1/1 size 11708072 chunksize
1048576
changer: opening pipe to: /usr/lib/amanda/chg-zd-mtx -info
setup_estimate: unixserver:/data/backup: command 0, options: none last_level
0 next_level0 0 level_days 0 getting estimates 0 (-2) -1 (-2) -1 (-2)
planner: time 0.022: setting up estimates took 0.009 secs
GETTING ESTIMATES...
planner: time 0.034: bind_portrange2: trying port=842
planner: time 0.034: dgram_bind: socket bound to 0.0.0.0.842
reserving 18853498 out of 1885349800 for degraded-mode dumps
driver: started dumper0 pid 4970
dumper: pid 4970 executable dumper0 version 2.5.0
driver: started dumper1 pid 4971
dumper: pid 4971 executable dumper1 version 2.5.0
driver: started dumper2 pid 4975
driver: started dumper3 pid 4976
driver: started dumper4 pid 4977
dumper: pid 4975 executable dumper2 version 2.5.0
dumper: pid 4976 executable dumper3 version 2.5.0
dumper: pid 4978 executable dumper5 version 2.5.0
dumper: pid 4977 executable dumper4 version 2.5.0
driver: started dumper5 pid 4978
driver: started dumper6 pid 4979
driver: started dumper7 pid 4980
driver: started dumper8 pid 4981
driver: started dumper9 pid 4982
driver: started dumper10 pid 4983
driver: started dumper11 pid 4984
driver: start time 0.072 inparallel 12 bandwidth 44000 diskspace 1885349800 dir
OBSOLETE datestamp 20060504 driver: drain-ends tapeq LARGESTFIT big-dumpers
BTTTSTSTSTS
dumper: pid 4979 executable dumper6 version 2.5.0
dumper: pid 4980 executable dumper7 version 2.5.0
dumper: pid 4982 executable dumper9 version 2.5.0
dumper: pid 4984 executable dumper11 version 2.5.0
dumper: pid 4983 executable dumper10 version 2.5.0
dumper: pid 4981 executable dumper8 version 2.5.0
changer: got exit: 0 str: 4 9 1 1
changer_query: changer return was 9 1 1
changer_query: searchable = 1
changer_find: looking for WEEKLY003 changer is searchable = 1
changer_search: WEEKLY003
changer: opening pipe to: /usr/lib/amanda/chg-zd-mtx -search WEEKLY003
planner: time 0.528: got partial result for host unixserver disk /data/backup:
0 -> -2K, -1 -> -2K, -1 -> -2K
changer: got exit: 2 str: <none> Line 221 malformed in
/etc/amanda/changer/chg-zd-mtx-barcodes: Set1-1-10
changer: opening pipe to: /usr/lib/amanda/chg-zd-mtx -slot current
changer: got exit: 0 str: 4 /dev/overland-sdlt600-tape
changer: opening pipe to: /usr/lib/amanda/chg-zd-mtx -slot next
changer: got exit: 0 str: 5 /dev/overland-sdlt600-tape
changer: opening pipe to: /usr/lib/amanda/chg-zd-mtx -slot next
planner: time 92.411: got partial result for host unixserver disk /data/backup:
0 -> 232420180K, -1 -> -2K, -1 -> -2K
planner: time 92.412: got result for host unixserver disk /data/backup: 0 ->
232420180K, -1 -> -2K, -1 -> -2K
planner: time 92.412: getting estimates took 92.389 secs
FAILED QUEUE: empty
DONE QUEUE:
0: unixserver /data/backup
ANALYZING ESTIMATES...
pondering unixserver:/data/backup... next_level0 0 last_level 0 (due for level
0) (picking inclevel for degraded mode) picklev: last night 0, so tonight
level 1
(no inc estimate)
curr level 0 size 197055206 total size 197055302 total_lev0 197055206
balanced-lev0size 39411041
INITIAL SCHEDULE (size 197055302):
unixserver /data/backup pri 1 lev 0 size 197055206
DELAYING DUMPS IF NEEDED, total_size 197055302, tape length 3735552000 mark 0
delay: Total size now 197055302.
PROMOTING DUMPS IF NEEDED, total_lev0 197055206, balanced_size 39411041...
planner: time 92.412: analysis took 0.000 secs
GENERATING SCHEDULE:
--------
DUMP unixserver fffffeff9ffe7f0000 /data/backup 20060504 1 0 1970:1:1:0:0:0
197055206 24200
--------
changer: got exit: 0 str: 6 /dev/overland-sdlt600-tape
changer: opening pipe to: /usr/lib/amanda/chg-zd-mtx -slot next
changer: got exit: 0 str: 7 /dev/overland-sdlt600-tape
changer: opening pipe to: /usr/lib/amanda/chg-zd-mtx -slot next
changer: got exit: 0 str: 8 /dev/overland-sdlt600-tape
changer: opening pipe to: /usr/lib/amanda/chg-zd-mtx -slot next
changer: got exit: 0 str: 9 /dev/overland-sdlt600-tape
changer: opening pipe to: /usr/lib/amanda/chg-zd-mtx -slot next
changer: got exit: 0 str: 1 /dev/overland-sdlt600-tape
changer: opening pipe to: /usr/lib/amanda/chg-zd-mtx -slot next
changer: got exit: 0 str: 2 /dev/overland-sdlt600-tape
changer: opening pipe to: /usr/lib/amanda/chg-zd-mtx -slot next
changer: got exit: 0 str: 3 /dev/overland-sdlt600-tape
slot 4: read label `Set1-Apr-04', date `20060430'
slot 5: read label `Set1-Apr-05', date `20060501'
slot 6: read label `Set1-Apr-06', date `20060501'
slot 7: read label `Set1-Apr-07', date `20060501'
slot 8: read label `Set1-Apr-08', date `20060501'
slot 9: read label `Set1-Apr-09', date `20060501'
slot 1: read label `Set1-Apr-01', date `20060430'
slot 2: read label `Set1-Apr-02', date `20060430'
slot 3: read label `Set1-Apr-03', date `20060430'
driver: result time 470.926 from taper: TAPE-ERROR [slot 4: read label
`Set1-Apr-04', date `20060430'
slot 5: read label `Set1-Apr-05', date `20060501'
slot 6: read label `Set1-Apr-06', date `20060501'
slot 7: read label `Set1-Apr-07', date `20060501'
slot 8: read label `Set1-Apr-08', date `20060501'
slot 9: read label `Set1-Apr-09', date `20060501'
slot 1: read label `Set1-Apr-01', date `20060430'
slot 2: read label `Set1-Apr-02', date `20060430'
slot 3: read label `Set1-Apr-03', date `20060430'
]
driver: state time 470.926 free kps: 44000 space: 1885349800 taper: idle
idle-dumpers: 12 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 0 driver-idle: not-idle
driver: interface-state time 470.926 if : free 44000
driver: hdisk-state time 470.926 hdisk 0: free 550800356 dumpers 0 hdisk 1:
free 138585904 dumpers 0 hdisk 2: free 65610248 dumpers 0 hdisk 3: free
564966916 dumpers 0 hdisk 4: free 138500524 dumpers 0 hdisk 5: free 289936068
dumpers 0 hdisk 6: free 125241712 dumpers 0 hdisk 7: free 11708072 dumpers 0
driver: flush size 0
dump of driver schedule before start degraded mode:
--------
unixserver /data/backup lv 0 t 24200 s 197055238
p 1
--------
dump of driver schedule after start degraded mode:
--------
unixserver /data/backup lv 0 t 24200 s 197055238
p 1
--------
driver: started chunker0 pid 7453
driver: send-cmd time 470.927 to chunker0: PORT-WRITE 00-00001
/var/spool/amanda/5/5/20060504174601/unixserver._data_backup.0 unixserver
fffffeff9ffe7f0000 /data/backup 0 1970:1:1:0:0:0 1048576 GNUTAR 197061280
|;auth=BSD;compress-fast;no-record;index;
chunker: pid 7453 executable chunker0 version 2.5.0
chunker: try_socksize: receive buffer size is 65536
chunker: bind_portrange2: trying port=50072
chunker: stream_server: waiting for connection: 0.0.0.0.50072
driver: result time 470.932 from chunker0: PORT 50072
driver: send-cmd time 470.932 to dumper0: PORT-DUMP 00-00001 50072 unixserver
fffffeff9ffe7f0000 /data/backup NODEVICE 0 1970:1:1:0:0:0 GNUTAR
|;auth=BSD;compress-fast;no-record;index;
dumper: bind_portrange2: trying port=50013
dumper: stream_client: connected to 127.0.0.1.50072
dumper: stream_client: our side is 0.0.0.0.50013
chunker: stream_accept: connection from 127.0.0.1.50013
dumper: try_socksize: send buffer size is 65536
chunker: try_socksize: receive buffer size is 32768
dumper: bind_portrange2: trying port=840
dumper: dgram_bind: socket bound to 0.0.0.0.840
dumper: bind_portrange2: trying port=50013
dumper: bind_portrange2: trying port=50014
dumper: stream_client: connected to 172.16.10.206.50033
dumper: stream_client: our side is 0.0.0.0.50014
dumper: try_socksize: send buffer size is 65536
dumper: try_socksize: receive buffer size is 65536
dumper: bind_portrange2: trying port=50013
dumper: bind_portrange2: trying port=50014
dumper: bind_portrange2: trying port=50015
dumper: stream_client: connected to 172.16.10.206.50034
dumper: stream_client: our side is 0.0.0.0.50015
dumper: try_socksize: send buffer size is 65536
dumper: try_socksize: receive buffer size is 65536
dumper: bind_portrange2: trying port=50013
dumper: bind_portrange2: trying port=50014
dumper: bind_portrange2: trying port=50015
dumper: bind_portrange2: trying port=50016
dumper: stream_client: connected to 172.16.10.206.50035
dumper: stream_client: our side is 0.0.0.0.50016
dumper: try_socksize: send buffer size is 65536
dumper: try_socksize: receive buffer size is 65536
driver: state time 29742.946 free kps: 35858 space: 1688288520 taper: DOWN
idle-dumpers: 11 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 0 driver-idle:
no-dumpers
driver: interface-state time 29742.946 if : free 35858
driver: hdisk-state time 29742.946 hdisk 0: free 550800356 dumpers 0 hdisk 1:
free 138585904 dumpers 0 hdisk 2: free 65610248 dumpers 0 hdisk 3: free
367905636 dumpers 1 hdisk 4: free 138500524 dumpers 0 hdisk 5: free 289936068
dumpers 0 hdisk 6: free 125241712 dumpers 0 hdisk 7: free 11708072 dumpers 0
driver: result time 29742.963 from chunker0: RQ-MORE-DISK 00-00001
driver: send-cmd time 29742.963 to chunker0: CONTINUE 00-00001
/var/spool/amanda/5/5/20060504174601/unixserver._data_backup.0 1048576 9853088
driver: state time 31115.921 free kps: 35858 space: 1678435432 taper: DOWN
idle-dumpers: 11 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 0 driver-idle:
no-dumpers
driver: interface-state time 31115.921 if : free 35858
driver: hdisk-state time 31115.921 hdisk 0: free 550800356 dumpers 0 hdisk 1:
free 138585904 dumpers 0 hdisk 2: free 65610248 dumpers 0 hdisk 3: free
358052548 dumpers 1 hdisk 4: free 138500524 dumpers 0 hdisk 5: free 289936068
dumpers 0 hdisk 6: free 125241712 dumpers 0 hdisk 7: free 11708072 dumpers 0
driver: result time 31115.937 from chunker0: RQ-MORE-DISK 00-00001
find diskspace: not enough diskspace. Left with 2412180312 K
find diskspace: not enough diskspace. Left with 2412180312 K
driver: Don't know how to send ABORT command to chunker
chunker: error [bad command after RQ-MORE-DISK: "QUIT"]
chunker: time 30645.022: error [bad command after RQ-MORE-DISK: "QUIT"]
chunker: time 30645.022: pid 7453 finish time Fri May 5 02:24:37 2006
taper: DONE [idle wait: 30645.029 secs]
dumper: kill index command
amdump: end at Fri May 5 02:24:37 CEST 2006
lp: nothing to print
amreport: printer command failed: /usr/bin/lpr
Scanning /var/spool/amanda/9/9...
20060504065747: found Amanda directory.
20060504070720: found Amanda directory.
20060504174601: found Amanda directory.
tmp: skipping cruft directory, perhaps you should delete it.
Scanning /var/spool/amanda/8/8...
20060504065747: found Amanda directory.
20060504070720: found Amanda directory.
20060504174601: found Amanda directory.
Scanning /var/spool/amanda/6/6...
20060504065747: found Amanda directory.
20060504070720: found Amanda directory.
20060504174601: found Amanda directory.
Scanning /var/spool/amanda/5/5...
20060430010625: found Amanda directory.
20060504065747: found Amanda directory.
20060504070720: found Amanda directory.
20060504174601: found Amanda directory.
Scanning /var/spool/amanda/4/4...
20060504065747: found Amanda directory.
20060504070720: found Amanda directory.
20060504174601: found Amanda directory.
Scanning /var/spool/amanda/3/3...
20060504065747: found Amanda directory.
20060504070720: found Amanda directory.
20060504174601: found Amanda directory.
Scanning /var/spool/amanda/2/2...
20060430010625: found Amanda directory.
20060504065747: found Amanda directory.
20060504070720: found Amanda directory.
20060504174601: found Amanda directory.
Scanning /var/spool/amanda/1/1...
20060504065747: found Amanda directory.
20060504070720: found Amanda directory.
20060504174601: found Amanda directory.
|
