Share to big to fit on a tape, but it should fit ...

[endfx]

When I run a full backup on one of my shares I get the following error:

FAILURE AND STRANGE DUMP SUMMARY:
server /files/private lev 2 FAILED [dump larger than tape, -1 KB, skipping incremental]

It seems obvious that my tape isn't big enough, but that can't be the case.
The tape is an lto-3 -> 400GB native.
The share is currently about 300 GB.

I just cleaned up the share to be 300 GB, it was almost at 400GB which would
perhaps be why it initially failed with the above error message. Now that I've shrunk
the share, why would I still get this error?

[martineau]

What amanda release are you using?
Older release have overflow problem with big disk.
Could you post the amdump.1 log file?

[endfx]

Ok, I think I've figured some more stuff out so let me describe my problem again:

We have a share that is too big to fit on a tape so the backup failed saying the share wouldn't fit on a tape.
I've shrunk the share so it will easily fit on a tape. The problem is, the backups still fail saying that the share
won't fit on a disk. As soon as I start the backup, it fails within a minute.

The thing is, when I make a new amanda configuration for this share, the backup runs just fine.
When I use my original configuration, amanda fails instantly.

My understanding is the amanda planner gets an estimated value for a share size. So I'm thinking
the amanda planner on my original configuration is using a cached value for the size of the share
and that’s why it keeps failing with my original config, but works with a new config.

Is it possible to reset the amanda planner cached values (if there is such a thing) for my original configuration/index/database files?


Thanks!

[endfx]

Oh, and to answer the question that I was asked:
I'm using amanda 2.4.5

DISK planner server /files/private
START planner date 20070326
WARNING planner tapecycle (1) <= runspercycle (1)
START driver date 20070326
STATS driver startup time 0.013
FAIL planner server /files/private 20070326 2 [dump larger than tape, -1 KB, skipping incremental]
FATAL planner cannot fit anything on tape, bailing out
START taper datestamp 20070326 label W00015 tape 0
WARNING driver WARNING: got empty schedule from planner
INFO taper tape W00015 kb 0 fm 0 [OK]
FINISH driver date 20070326 time 4.417


This is why I think the planner is using a cached value.

[martineau]

What's the output of : amadmin <config> info server /files/private
The problem might be in the compression ratio, they are in the
curinfo/server/_files_privates/info file

[endfx]

Current info for server /files/private:
Stats: dump rates (kps), Full: 1872.0, 2466.0, 2464.0
Incremental: -1.0, -1.0, -1.0
compressed size, Full: 53.1%, 54.1%, 54.1%
Incremental: -100.0%,-100.0%,-100.0%
Dumps: lev datestmp tape file origK compK secs
0 19691231 0 -1 -1 -1


Comparing the output of above to some of my other shares, it looks pretty much the same except for the last line (because my other share has been completing its backup)

This doesn't make much sense to me. Do you see a problem or any errors in here?


Thanks for your help.

[martineau]

The info looks good.
Could you post the amdump.1 log file

[endfx]

Ok, here is my amdump.1 log file:
After looking at it, I see that it is the planner that is causing the failure:

-----------------------------------------------------------------------------------------

amdump: start at Wed Mar 28 10:45:59 CST 2007
amdump: datestamp 20070328
driver: pid 5850 executable /usr/lib/amanda/driver version 2.4.5
planner: pid 5849 executable /usr/lib/amanda/planner version 2.4.5
planner: build: VERSION="Amanda-2.4.5"
planner: BUILT_DATE="Thu Jun 9 09:26:39 UTC 2005"
planner: BUILT_MACH="Linux vernadsky 2.6.10 #1 SMP Fri May 13 09:24:22 UTC 2005 i686 GNU/Linux"
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-tcpportrange=50000,50100' '--with-udpportrange=840,860'"
planner: paths: bindir="/usr/sbin" sbindir="/usr/sbin"
planner: libexecdir="/usr/lib/amanda" mandir="/usr/share/man"
planner: AMANDA_TMPDIR="/tmp/amanda" AMANDA_DBGDIR="/tmp/amanda"
planner: CONFIG_DIR="/etc/amanda" DEV_PREFIX="/dev/"
planner: 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="/dev/null" HAVE_MMAP HAVE_SYSVSHM
planner: LOCKING=POSIX_FCNTL SETPGRP_VOID DEBUG_CODE
planner: AMANDA_DEBUG_DAYS=4 BSD_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"
planner: time 0.000: dgram_bind: socket bound to 0.0.0.0.850
READING CONF FILES...
driver: tape size 411041792
driver: send-cmd time 0.028 to taper: START-TAPER 20070328
driver: adding holding disk 0 dir /backup size 732810400 chunksize 1048576
reserving 732810400 out of 732810400 for degraded-mode dumps
driver: started dumper0 pid 5852
driver: started dumper1 pid 5853
driver: started dumper2 pid 5854
driver: started dumper3 pid 5855
driver: started dumper4 pid 5856
driver: started dumper5 pid 5857
driver: started dumper6 pid 5858
driver: started dumper7 pid 5859
driver: started dumper8 pid 5860
driver: started dumper9 pid 5861
taper: pid 5851 executable taper version 2.4.5
dumper: dgram_bind: socket bound to 0.0.0.0.853
dumper: pid 5852 executable dumper0 version 2.4.5, using port 853
dumper: dgram_bind: socket bound to 0.0.0.0.854
dumper: pid 5853 executable dumper1 version 2.4.5, using port 854
dumper: dgram_bind: socket bound to 0.0.0.0.855
dumper: pid 5854 executable dumper2 version 2.4.5, using port 855
dumper: dgram_bind: socket bound to 0.0.0.0.856
dumper: pid 5855 executable dumper3 version 2.4.5, using port 856
dumper: dgram_bind: socket bound to 0.0.0.0.858
dumper: pid 5857 executable dumper5 version 2.4.5, using port 858
dumper: dgram_bind: socket bound to 0.0.0.0.859
dumper: pid 5858 executable dumper6 version 2.4.5, using port 859
dumper: dgram_bind: socket bound to 0.0.0.0.857
dumper: pid 5856 executable dumper4 version 2.4.5, using port 857
dumper: dgram_bind: socket bound to 0.0.0.0.860
dumper: pid 5859 executable dumper7 version 2.4.5, using port 860
dumper: dgram_bind: socket bound to 0.0.0.0.840
dumper: pid 5860 executable dumper8 version 2.4.5, using port 840
dumper: dgram_bind: socket bound to 0.0.0.0.841
dumper: pid 5861 executable dumper9 version 2.4.5, using port 841
taper: page size is 4096
taper: buffer size is 32768
taper: buffer[00] at 0xb7c78000
taper: buffer[01] at 0xb7c80000
planner: time 0.056: startup took 0.056 secs
taper: buffer[02] at 0xb7c88000

SENDING FLUSHES...
taper: buffer[03] at 0xb7c90000
ENDFLUSH
taper: buffer[04] at 0xb7c98000
taper: buffer[05] at 0xb7ca0000
taper: buffer[06] at 0xb7ca8000

SETTING UP FOR ESTIMATES...
taper: buffer[07] at 0xb7cb0000
planner: time 0.056: setting up estimates for server:/files/private
taper: buffer[08] at 0xb7cb8000
taper: buffer[09] at 0xb7cc0000
taper: buffer[10] at 0xb7cc8000
taper: buffer[11] at 0xb7cd0000
taper: buffer[12] at 0xb7cd8000
taper: buffer[13] at 0xb7ce0000
taper: buffer[14] at 0xb7ce8000
taper: buffer[15] at 0xb7cf0000
taper: buffer[16] at 0xb7cf8000
taper: buffer[17] at 0xb7d00000
taper: buffer[18] at 0xb7d08000
taper: buffer[19] at 0xb7d10000
taper: buffer structures at 0xb7d18000 for 240 bytes
setup_estimate: server:/files/private: command 0, options: none last_level 0 next_level0 0 level_days 0 getting estimates 0 (-2) -1 (-2) -1 (-2)
planner: time 0.057: setting up estimates took 0.000 secs

GETTING ESTIMATES...
driver: flush size 0
driver: start time 0.057 inparallel 10 bandwidth 10752000 diskspace 732810400 dir OBSOLETE datestamp 20070328 driver: drain-ends tapeq FIRST big-dumpers TSTSTSTSTs
changer: opening pipe to: /usr/lib/amanda/chg-zd-mtx -info
planner time 0.167: got result for host server disk /files/private: 0 -> -1K, -1 -> -2K, -1 -> -2K
planner: time 0.167: getting estimates took 0.110 secs
FAILED QUEUE: empty
DONE QUEUE:
0: server /files/private

ANALYZING ESTIMATES...
pondering server:/files/private... next_level0 0 last_level 0 (due for level 0) (no estimate for level 0, picking an incr level)
picklev: last night 0, so tonight level 1
curr level 2 size -1 total size 95 total_lev0 0 balanced-lev0size -1
INITIAL SCHEDULE (size 95):
server /files/private pri 2 lev 2 size -1

DELAYING DUMPS IF NEEDED, total_size 95, tape length 1233125376 mark 0
planner: FAILED server /files/private 20070328 2 [dump larger than tape, -1 KB, skipping incremental]
delay: Total size now 64.
planner: cannot fit anything on tape, bailing out
planner: time 0.167: cannot fit anything on tape, bailing out
planner: time 0.167: pid 5849 finish time Wed Mar 28 10:45:59 2007
changer: got exit: 0 str: 2 1 1 1
changer_query: changer return was 1 1 1
changer_query: searchable = 1
changer_find: looking for W00015 changer is searchable = 1
changer_search: W00015
changer: opening pipe to: /usr/lib/amanda/chg-zd-mtx -search W00015
changer: got exit: 2 str: <none> barcode "W00015" not found in mtx status output
changer: opening pipe to: /usr/lib/amanda/chg-zd-mtx -slot current
changer: got exit: 0 str: 2 /dev/nst0
taper: slot 2: date 20070327 label W00005 (active tape)
driver: result time 0.890 from taper: TAPE-ERROR [label W00015 or new tape not found in rack]
dump of driver schedule before start degraded mode:
--------
--------
dump of driver schedule after start degraded mode:
--------
--------
driver: state time 0.890 free kps: 10752000 space: 732810400 taper: DOWN idle-dumpers: 10 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 86400 driver-idle: not-idle
driver: interface-state time 0.890 if : free 512000 if ETH0: free 10240000
driver: hdisk-state time 0.890 hdisk 0: free 732810400 dumpers 0
driver: state time 0.890 free kps: 10752000 space: 732810400 taper: DOWN idle-dumpers: 10 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 86400 driver-idle: not-idle
driver: interface-state time 0.890 if : free 512000 if ETH0: free 10240000
driver: hdisk-state time 0.890 hdisk 0: free 732810400 dumpers 0
driver: QUITTING time 0.890 telling children to quit
driver: send-cmd time 0.890 to dumper0: QUIT
driver: send-cmd time 0.890 to dumper1: QUIT
driver: send-cmd time 0.890 to dumper2: QUIT
driver: send-cmd time 0.890 to dumper3: QUIT
driver: send-cmd time 0.890 to dumper4: QUIT
driver: send-cmd time 0.890 to dumper5: QUIT
driver: send-cmd time 0.890 to dumper6: QUIT
driver: send-cmd time 0.890 to dumper7: QUIT
driver: send-cmd time 0.891 to dumper8: QUIT
driver: send-cmd time 0.891 to dumper9: QUIT
driver: send-cmd time 0.891 to taper: QUIT
taper: DONE [idle wait: 0.000 secs]
driver: FINISHED time 0.892
amdump: end at Wed Mar 28 10:46:00 CST 2007
Scanning /backup...

------------------------------------------------------------------------------

Thanks for your help.

[martineau]

The line:
planner time 0.167: got result for host server disk /files/private: 0 -> -1K, -1 -> -2K, -1 -> -2K

tell us that the client didn't send valid estimate, could you post the sendsize.*.debug file

[endfx]

I've checked both the client and server log files and I don't see a sendsize log file.
Is there an option I can specify in the amanda.conf to turn on log files for sendsize?

amadmin x version | grep DBG
shows amanda puts its debug files in /tmp/amanda so I'm pretty sure I'm looking in the right place.

Any ideas as to why I'm not getting a sendsize log file?

Thanks.