PDA

View Full Version : amrecover failure



grouch53
September 7th, 2010, 11:34 PM
Hi folks

after some struggling I finally got my amanda installation up and running apparently smoothly on a iscsi connected REO changer.

Daily backups report success all over, so I tried a recover today just to see if it really was that smoothly.

Here is the amreport from last night for your reference

Hostname: amanda
Org : Ruf
Config : DailySet1
Date : September 8, 2010

These dumps were to tape amanda-0003.
The next tape Amanda expects to use is: 1 new tape.
The next new tape already labelled is: amanda-0004.


STATISTICS:
Total Full Incr.
-------- -------- --------
Estimate Time (hrs:min) 0:10
Run Time (hrs:min) 0:26
Dump Time (hrs:min) 0:25 0:17 0:09
Output Size (meg) 3202.5 3190.1 12.4
Original Size (meg) 6223.9 6194.0 30.0
Avg Compressed Size (%) 51.5 51.5 41.4 (level:#disks ...)
Filesystems Dumped 13 9 4 (1:4)
Avg Dump Rate (k/s) 2158.8 3271.4 24.4

Tape Time (hrs:min) 0:08 0:08 0:00
Tape Size (meg) 3202.5 3190.1 12.4
Tape Used (%) 1.7 1.7 0.0 (level:#disks ...)
Filesystems Taped 13 9 4 (1:4)
(level:#parts ...)
Parts Taped 13 9 4 (1:4)
Avg Tp Write Rate (k/s) 6729.7 6735.4 5515.2

USAGE BY TAPE:
Label Time Size % Nb Nc
amanda-0003 0:08 3203M 1.7 13 13

NOTES:
planner: Full dump of amanda.ruf.ch:/var promoted from 2 days ahead.
planner: Full dump of srvx-lx01-afa.ruf.group:/var promoted from 2 days ahead.
planner: Full dump of subversion.ruf.ch:/var promoted from 2 days ahead.
planner: Full dump of amanda.ruf.ch:/usr promoted from 2 days ahead.
planner: Full dump of srvx-lx01-afa.ruf.group:/usr promoted from 2 days ahead.
planner: Full dump of subversion.ruf.ch:/usr promoted from 2 days ahead.
planner: Full dump of amanda.ruf.ch:/ promoted from 2 days ahead.
planner: Full dump of subversion.ruf.ch:/ promoted from 2 days ahead.
planner: Full dump of srvx-lx01-afa.ruf.group:/ promoted from 2 days ahead.
taper: tape amanda-0003 kb 3279376 fm 13 [OK]


DUMP SUMMARY:
DUMPER STATS TAPER STATS
HOSTNAME DISK L ORIG-MB OUT-MB COMP% MMM:SS KB/s MMM:SS KB/s
-------------------------- -------------------------------------- -------------
amanda.ruf.c / 0 144 144 -- 0:18 8385.2 0:19 7775.3
amanda.ruf.c /home 1 1 0 0.6 0:20 0.5 0:00 90.0
amanda.ruf.c /usr 0 483 189 39.2 0:46 4180.5 0:27 7170.9
amanda.ruf.c /var 0 1446 732 50.6 2:11 5717.0 2:04 6044.4
srvx-lx01-af / 0 239 239 -- 1:24 2922.1 0:37 6626.2
srvx-lx01-af /home 1 1 0 0.4 4:27 0.0 0:00 60.0
srvx-lx01-af /usr 0 448 167 37.3 2:48 1018.4 0:29 5904.8
srvx-lx01-af /var 0 1355 650 47.9 5:09 2153.5 1:18 8530.9
subversion.r / 0 148 148 -- 0:09 16870.5 0:28 5422.1
subversion.r /data 1 26 12 48.1 3:32 59.8 0:02 6332.0
subversion.r /home 1 1 0 0.4 0:22 0.3 0:00 60.0
subversion.r /usr 0 483 189 39.2 2:02 1588.8 0:26 7447.3
subversion.r /var 0 1446 731 50.5 1:52 6705.7 1:57 6398.1

(brought to you by Amanda version 3.1.2)

I now tried to recover some files from one of my client machines

subversion:/home/administrator# amrecover
AMRECOVER Version 3.1.2. Contacting server on amanda.ruf.ch ...
220 amanda AMANDA index server (3.1.2) ready.
Setting restore date to today (2010-09-08)
200 Working date set to 2010-09-08.
200 Config set to DailySet1.
501 Host subversion is not in your disklist.
Trying host subversion ...
501 Host subversion is not in your disklist.
Trying host subversion.ruf.ch ...
200 Dump host set to subversion.ruf.ch.
Use the setdisk command to choose dump disk to recover

amrecover> listdisk
200- List of disk for host subversion.ruf.ch
201- /
201- /home
201- /var
201- /usr
201- /data
201- /backup
200 List of disk for host subversion.ruf.ch

amrecover> setdisk /data
200 Disk set to /data.

amrecover> ls
2010-09-08-01-00-02 svn/
2010-09-08-01-00-02 .
2010-09-04-01-00-01 lost+found/
2010-09-04-01-00-01 amanda/

amrecover> ls
2010-09-08-01-00-02 svn/
2010-09-08-01-00-02 .
2010-09-04-01-00-01 lost+found/
2010-09-04-01-00-01 amanda/
amrecover> lcd /tmp
amrecover> cd svn
/data/svn
amrecover> cd repositories
/data/svn/repositories
amrecover> ls
2010-09-08-01-00-02 wwrepos2/
2010-09-08-01-00-02 ruf_informatik/
2010-09-08-01-00-02 RT_DevCom/
2010-09-08-01-00-02 .
2010-09-04-01-00-01 wwrepos3/
2010-09-04-01-00-01 U2/
2010-09-04-01-00-01 SI-repository/

amrecover> add U2
Added dir /svn/repositories/U2/ at date 2010-09-04-01-00-01
amrecover> extract

Extracting files using tape drive changer on host amanda.ruf.ch.
The following tapes are needed: amanda-0001

Extracting files using tape drive changer on host amanda.ruf.ch.
Load tape amanda-0001 now
Continue [?/Y/n/s/d]? Y
Restoring files into directory /tmp
All existing files in /tmp can be deleted
Continue [?/Y/n]? Y

Checksum error 0, inode 0 file (null)
restore: Tape is not a dump tape

OK I killed the process and went to the amanda server to look at the tape library

amandabackup@amanda:~$ mtx -f /dev/tapeloader0 status
Storage Changer /dev/tapeloader0:1 Drives, 10 Slots ( 0 Import/Export )
Data Transfer Element 0:Full (Storage Element 1 Loaded):VolumeTag = AAB001
Storage Element 1:Empty
Storage Element 2:Full :VolumeTag=AAB002
Storage Element 3:Full :VolumeTag=AAB003
Storage Element 4:Full :VolumeTag=AAB004
Storage Element 5:Full :VolumeTag=AAB005
Storage Element 6:Full :VolumeTag=AAB006
Storage Element 7:Full :VolumeTag=AAB007
Storage Element 8:Full :VolumeTag=AAB008
Storage Element 9:Full :VolumeTag=AAB009
Storage Element 10:Full :VolumeTag=AAB010

This looks like the correct tape has been loaded.

I dumped the tape contents

amandabackup@amanda:/etc/amanda$ mt -f /dev/nst0 rewind
amandabackup@amanda:/etc/amanda$ dd if=/dev/nst0 count=1 | od -xc | more
1+0 records in
1+0 records out
512 bytes (512 B) copied, 0.00383082 s, 134 kB/s
0000000 4d41 4e41 4144 203a 4154 4550 5453 5241
A M A N D A : T A P E S T A R
0000020 2054 4144 4554 3220 3130 3030 3039 3034
T D A T E 2 0 1 0 0 9 0 4 0
0000040 3031 3030 2031 4154 4550 6120 616d 646e
1 0 0 0 1 T A P E a m a n d
0000060 2d61 3030 3130 0c0a 000a 0000 0000 0000
a - 0 0 0 1 \n \f \n \0 \0 \0 \0 \0 \0 \0
0000100 0000 0000 0000 0000 0000 0000 0000 0000
\0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0
*
0001000
amandabackup@amanda:/etc/amanda$ mt -f /dev/nst0 rewind
amandabackup@amanda:/etc/amanda$ mt -f /dev/nst0 fsf 1
amandabackup@amanda:/etc/amanda$ dd if=/dev/nst0 count=1 | od -xc | more
1+0 records in
1+0 records out
512 bytes (512 B) copied, 0.00399268 s, 128 kB/s
0000000 4d41 4e41 4144 203a 5053 494c 5f54 4946
A M A N D A : S P L I T _ F I
0000020 454c 3220 3130 3030 3039 3034 3031 3030
L E 2 0 1 0 0 9 0 4 0 1 0 0 0
0000040 2031 6d61 6e61 6164 722e 6675 632e 2068
1 a m a n d a . r u f . c h
0000060 682f 6d6f 2065 7020 7261 2074 2f31 312d
/ h o m e p a r t 1 / - 1
0000100 2020 656c 2076 2031 6f63 706d 2e20 7a67
l e v 1 c o m p . g z
0000120 7020 6f72 7267 6d61 2f20 6273 6e69 642f
p r o g r a m / s b i n / d
0000140 6d75 0a70 524f 4749 4953 455a 313d 3534
u m p \n O R I G S I Z E = 1 4 5
0000160 0a35 4c44 3d45 3c3c 4e45 4444 454c 3c0a
5 \n D L E = < < E N D D L E \n <
0000200 6c64 3e65 200a 3c20 7270 676f 6172 3e6d
d l e > \n < p r o g r a m >
0000220 5544 504d 2f3c 7270 676f 6172 3e6d 200a
D U M P < / p r o g r a m > \n
0000240 3c20 6964 6b73 2f3e 6f68 656d 2f3c 6964
< d i s k > / h o m e < / d i
0000260 6b73 0a3e 2020 6c3c 7665 6c65 313e 2f3c
s k > \n < l e v e l > 1 < /
0000300 656c 6576 3e6c 200a 3c20 7561 6874 423e
l e v e l > \n < a u t h > B
0000320 4453 2f3c 7561 6874 0a3e 2020 633c 6d6f
S D < / a u t h > \n < c o m
0000340 7270 7365 3e73 4146 5453 2f3c 6f63 706d
p r e s s > F A S T < / c o m p
0000360 6572 7373 0a3e 2020 723c 6365 726f 3e64
r e s s > \n < r e c o r d >
0000400 4559 3c53 722f 6365 726f 3e64 200a 3c20
Y E S < / r e c o r d > \n <
0000420 6e69 6564 3e78 4559 3c53 692f 646e 7865
i n d e x > Y E S < / i n d e x
0000440 0a3e 2020 643c 7461 7061 7461 3e68 4d41
> \n < d a t a p a t h > A M
0000460 4e41 4144 2f3c 6164 6174 6170 6874 0a3e
A N D A < / d a t a p a t h > \n
0000500 2f3c 6c64 3e65 450a 444e 4c44 0a45 6f54
< / d l e > \n E N D D L E \n T o
0000520 7220 7365 6f74 6572 202c 6f70 6973 6974
r e s t o r e , p o s i t i
0000540 6e6f 7420 7061 2065 7461 7320 6174 7472
o n t a p e a t s t a r t
0000560 6f20 2066 6966 656c 6120 646e 7220 6e75
o f f i l e a n d r u n
0000600 0a3a 6409 2064 6669 3c3d 6174 6570 203e
: \n \t d d i f = < t a p e >
0000620 7362 333d 6b32 7320 696b 3d70 2031 207c
b s = 3 2 k s k i p = 1 |
0000640 622f 6e69 672f 697a 2070 642d 2063 207c
/ b i n / g z i p - d c |
0000660 732f 6962 2f6e 6572 7473 726f 2065 782d
/ s b i n / r e s t o r e - x
0000700 4770 2066 202d 2e2e 202e 0c0a 000a 0000
p G f - . . . \n \f \n \0 \0 \0
0000720 0000 0000 0000 0000 0000 0000 0000 0000
\0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0 \0
*
0001000

This looks like a amanda tape, the tape drive specified in the amanda config is

tapetype OVERLAND-REO # what kind of tape it is (see tapetypes below)
labelstr "^amanda-[0-9][0-9]*$" # label constraint regex: all tapes must match


define tapetype OVERLAND-REO {
comment "Created by amtapetype; compression disabled"
length 195150272 kbytes
filemark 32 kbytes
speed 7991 kps
blocksize 32 kbytes
}

>>>>>>>>>>>>>>>>>>>>>>>>

here is the changer definition from a main config file

# To use a tape library, uncomment this definition. See amanda-changers(7)
# for more configuration options.
#
define changer OVERLAND-REO {
tpchanger "chg-robot:/dev/sg0" # your changer device file
property "tape-device" "0=tape:/dev/nst0"
}
tapedev "OVERLAND-REO"

So it looks like the tape has been created, but somehow amrecover does not appear to be able to extract the data correctly from the tape. Using the mt commands on /dev/nst0 it looks like the tape behaves correctly. It appears to have a label, tapemark and some data, but recover does not seem to position itself correctly.

I extracted the various blocks on tape with dd and tried to find the data. The first 6 files on the tape appeared to be label and/or index only. File #7 had some content. It looks like there is data in these blocks at offset 32k as suggested by the command in the header of each block.

So I would be able to somehow get at the data, but well....

cheers

Erich

wsanders
September 8th, 2010, 10:29 AM
I am having a similar problem on Solaris 10, I suspect filemarks are not being handled correctly. I get a different error from tarL

/opt/csw/bin/gtar: Unexpected EOF in archive

I have not gotten to the point where I am checking a tape with dd like you did - I might get to that today.

grouch53
September 9th, 2010, 04:44 AM
I am having a similar problem on Solaris 10, I suspect filemarks are not being handled correctly. I get a different error from tarL

/opt/csw/bin/gtar: Unexpected EOF in archive

I have not gotten to the point where I am checking a tape with dd like you did - I might get to that today.

I _guess_ you are right, I am running this on a virtual Debial Lenny, but I think it really does not matter. Either the offset in the various datablocks are not used correctly or indeed the tapemark is not correctly handled.

I don't know where amrecover gets the file list from, I _guess_ it gets it from the index.

Do you know of a debugging method for amanda?

cheers

Erich

grouch53
September 9th, 2010, 06:10 AM
Hi folks

I believe I found a reason for this failure

Looking at the debug output the following shows up

Wed Sep 8 08:38:47 2010: amrecover: send_to_tape_server: FEATURES=ffffffff9efefbffffffffff01

Wed Sep 8 08:38:47 2010: amrecover: send_to_tape_server: CONFIG=DailySet1

Wed Sep 8 08:38:47 2010: amrecover: send_to_tape_server: LABEL=amanda-0001:13,14,15

Wed Sep 8 08:38:47 2010: amrecover: send_to_tape_server: FSF=13

Wed Sep 8 08:38:47 2010: amrecover: send_to_tape_server: HEADER

Wed Sep 8 08:38:47 2010: amrecover: send_to_tape_server: DEVICE=changer

Wed Sep 8 08:38:47 2010: amrecover: send_to_tape_server: HOST=^subversion.ruf.ch$

Wed Sep 8 08:38:47 2010: amrecover: send_to_tape_server: DISK=^/data$

Wed Sep 8 08:38:47 2010: amrecover: send_to_tape_server: DATESTAMP=20100904010001

Wed Sep 8 08:38:47 2010: amrecover: send_to_tape_server: END

Wed Sep 8 08:38:56 2010: amrecover: User prompt: 'Continue [?/Y/n]? '; response: 'Y'
Wed Sep 8 08:38:56 2010: amrecover: send_to_tape_server: AVAIL-DATAPATH AMANDA

Wed Sep 8 08:38:56 2010: amrecover: get amidxtaped line: USE-DATAPATH AMANDA
Wed Sep 8 08:38:56 2010: amrecover: Using AMANDA data-path
Wed Sep 8 08:38:56 2010: amrecover: send_to_tape_server: DATAPATH-OK

Wed Sep 8 08:38:56 2010: amrecover: Exec'ing /sbin/restore with arguments:
Wed Sep 8 08:38:56 2010: amrecover: restore
Wed Sep 8 08:38:56 2010: amrecover: xbf
Wed Sep 8 08:38:56 2010: amrecover: 2
Wed Sep 8 08:38:56 2010: amrecover: -
Wed Sep 8 08:38:56 2010: amrecover: /svn/repositories/U2

which makes me believe that on the server the following should be executed

forward 13 files on the tape then read the data into restore and extract svn....

Now looking at the information in the file itself the following command is suggested

0000720 3a6e 090a 6464 6920 3d66 743c 7061 3e65
n : \n \t d d i f = < t a p e >
0000740 6220 3d73 3233 206b 6b73 7069 313d 7c20
b s = 3 2 k s k i p = 1 |
0000760 2f20 6962 2f6e 7a67 7069 2d20 6364 7c20
/ b i n / g z i p - d c |
0001000 2f20 6273 6e69 722f 7365 6f74 6572 2d20
/ s b i n / r e s t o r e -
0001020 7078 6647 2d20 2e20 2e2e 0a20 0a0c 0000
x p G f - . . . \n \f \n \0 \0
0001040 0000 0000 0000 0000 0000 0000 0000 0000

So ...

dd if=/dev/nst0 bs=32k skip=1 | /bin/gzip - dc | /sbin/restore -xpGf - <whatever>

I extracted the file with

dd if=/dev/nst0 bs=32k skip=1 of=part13

and unzipped it with gzip .... and after a while I got

amanda:/amanda-holding# ls
lost+found part13
amanda:/amanda-holding# mv part13 part13.gz
amanda:/amanda-holding# gunzip part13.gz

gzip: part13.gz: unexpected end of file

booohh....

It smells like a bug, I will go back to uncompressed backup types and report later

cheers

Erich