PDA

View Full Version : Segmentation Fault During "Extract"



ddenton
June 14th, 2007, 07:03 AM
When I run the amrecover command from the client machine and attempt to run "extract", I get a segmentation fault. I don't get any faults during the browsing of files, like some other posts have implied.

Below is the only log file I could find that had changed since the last extract failure. It was found in /tmp/amanda/client/DailySet1/. Sorry, it's lengthy...

>>
amrecover: debug 1 pid 6127 ruid 0 euid 0: start at Thu Jun 14 09:44:04 2007
Reading conf file "/etc/amanda/amanda-client.conf".
Could not open conf file "/etc/amanda/DailySet1/amanda-client.conf": No such file or directory
amrecover: debug 1 pid 6127 ruid 0 euid 0: rename at Thu Jun 14 09:44:04 2007
security_getdriver(name=bsdtcp) returns 0x996140
security_handleinit(handle=0x9078530, driver=0x996140 (BSDTCP))
security_streaminit(stream=0x9079188, driver=0x996140 (BSDTCP))
amrecover: connect_port: Skip port 512: Owned by exec.
amrecover: connect_port: Skip port 513: Owned by login.
amrecover: connect_port: Skip port 514: Owned by shell.
amrecover: connect_port: Skip port 515: Owned by printer.
amrecover: connect_port: Try port 516: Available -
amrecover: connected to 192.168.100.228.10080
amrecover: our side is 0.0.0.0.516
amrecover: try_socksize: send buffer size is 65536
amrecover: try_socksize: receive buffer size is 65536
security_streaminit(stream=0x90822e8, driver=0x996140 (BSDTCP))
security_close(handle=0x9078530, driver=0x996140 (BSDTCP))
security_stream_close(0x9079188)
add_dir_list_item: Adding "2007-06-13-08-54-08" "0" "DailySet1-02:1" "1" "/.bash_logout"
add_dir_list_item: Adding "2007-06-13-08-54-08" "0" "DailySet1-02:1" "1" "/.bash_profile"
add_dir_list_item: Adding "2007-06-13-08-54-08" "0" "DailySet1-02:1" "1" "/.bashrc"
add_dir_list_item: Adding "2007-06-13-08-54-08" "0" "DailySet1-02:1" "1" "/.emacs"
add_dir_list_item: Adding "2007-06-13-08-54-08" "0" "DailySet1-02:1" "1" "/.gtkrc"
add_dir_list_item: Adding "2007-06-14-09-44-19" "2" "DailySet1-10:1" "1" "/."
add_dir_list_item: Adding "2007-06-14-09-44-19" "2" "DailySet1-10:1" "1" "/.am_passphrase"
add_dir_list_item: Adding "2007-06-14-09-44-19" "2" "DailySet1-10:1" "1" "/.bash_history"
add_dir_list_item: Adding "2007-06-14-09-44-19" "2" "DailySet1-10:1" "1" "/.ssh/"
add_dir_list_item: Adding "2007-06-14-09-44-19" "2" "DailySet1-10:1" "1" "/amrecover.20070614091529.debug"
add_dir_list_item: Adding "2007-06-14-09-44-19" "2" "DailySet1-10:1" "1" "/disk"
add_dir_list_item: Adding "2007-06-14-09-44-19" "2" "DailySet1-10:1" "1" "/testfile2.txt"
add_glob (testfile2.txt) -> ^testfile2\.txt$
add_file: Looking for "testfile2\.txt[/]*$"
add_file: Converted path="testfile2\.txt[/]*$" to path_on_disk="/testfile2\.txt[/]*$"
add_file: Pondering ditem->path=/testfile2.txt
add_file: (Successful) Added /testfile2.txt
add_file: Pondering ditem->path=/disk
add_file: Pondering ditem->path=/amrecover.20070614091529.debug
add_file: Pondering ditem->path=/.ssh/
add_file: Pondering ditem->path=/.bash_history
add_file: Pondering ditem->path=/.am_passphrase
add_file: Pondering ditem->path=/.
add_file: Pondering ditem->path=/.gtkrc
add_file: Pondering ditem->path=/.emacs
add_file: Pondering ditem->path=/.bashrc
add_file: Pondering ditem->path=/.bash_profile
add_file: Pondering ditem->path=/.bash_logout
append_to_tapelist(tapelist=(nil), label='DailySet1-10', , file=-1, isafile=0)
dump_tapelist(0x90788d8):
0x90788d8->next = (nil)
0x90788d8->label = DailySet1-10
0x90788d8->isafile = 0
0x90788d8->numfiles = 0
0x90788d8 count = 1
append_to_tapelist(tapelist=0x90788d8, label='DailySet1-10', , file=1, isafile=0)
dump_tapelist(0x90788d8):
0x90788d8->next = (nil)
0x90788d8->label = DailySet1-10
0x90788d8->isafile = 0
0x90788d8->numfiles = 1
0x90788d8->files[0] = 1
0x90788d8 count = 1
append_to_tapelist(tapelist=(nil), label='DailySet1-10', , file=-1, isafile=0)
dump_tapelist(0x90788c0):
0x90788c0->next = (nil)
0x90788c0->label = DailySet1-10
0x90788c0->isafile = 0
0x90788c0->numfiles = 0
0x90788c0 count = 1
security_getdriver(name=bsdtcp) returns 0x996140
security_handleinit(handle=0x9079990, driver=0x996140 (BSDTCP))
security_seterror(handle=0x9079990, driver=0x996140 (BSDTCP) error=DailySet1-10: could not resolve hostname)
security_close(handle=0x9079990, driver=0x996140 (BSDTCP))
security_handleinit(handle=0x9079990, driver=0x996140 (BSDTCP))
security_seterror(handle=0x9079990, driver=0x996140 (BSDTCP) error=DailySet1-10: could not resolve hostname)
security_close(handle=0x9079990, driver=0x996140 (BSDTCP))
security_handleinit(handle=0x9079990, driver=0x996140 (BSDTCP))
security_seterror(handle=0x9079990, driver=0x996140 (BSDTCP) error=DailySet1-10: could not resolve hostname)
<<

The first few lines are interesting, becuase the /etc/amanda/amanda-client.conf file does exist, is owned by amandabackup:disk, and has read and execute permissions for everyone. The last few lines have me baffled. From the client I can ping the IP of the server as well as the hostname and FDQN. It works from the server to the client as well. I even edited the amanda-client.conf to have the IP of the index server instead of the name, but that made no difference. And again, everything up to this point has worked.

Thanks for any assistance.

dustin
June 14th, 2007, 08:03 AM
This is actually a known bug, fixed in 2.5.2p1. If you can upgrade, please do so. If not, what are you specifying as the tape to use?

It looks like you're specifying something like
DailySet1-10:1
The colon in there causes the first part of the string to be used as a hostname, which fails, and that caused a segmentation fault in 2.5.2.

If I'm not clear, please post a transcript of your amrecover session starting with 'extract'.

ddenton
June 14th, 2007, 08:32 AM
If I don't specify the tape, then I get the following:

Load tape DailySet1-10 now
Continue [?/Y/n/s/t]?
tar: ./testfile2.txt: Not found in archive
tar: Error exit delayed from previous errors
Extractor child exited with status 2

I was using DailySet1-10:1 in the settape command because this was listed in the history output:

201- 2007-06-14-09-44-19 2 DailySet1-10:1

I'd rather not contend with an upgrade right now because it was a 2-week long slog just to get to this point with the current version. If possible, I'd like to get it working and then worry about the upgrade. Below is a transcript of my commands, using the syntax that gives the above error.

FYI - TESTBED001 is my server, TESTBED002 is my client.

[root@TESTBED002 amanda]# /usr/sbin/amrecover
AMRECOVER Version 2.5.1p2. Contacting server on TESTBED001 ...
220 TESTBED001 AMANDA index server (2.5.1p2) ready.
Setting restore date to today (2007-06-14)
200 Working date set to 2007-06-14.
200 Config set to DailySet1.
501 Host TESTBED002 is not in your disklist.
Trying host TESTBED002 ...
501 Host TESTBED002 is not in your disklist.
Trying host localhost.localdomain ...
501 Host localhost.localdomain is not in your disklist.
Trying host localhost ...
501 Host localhost is not in your disklist.
Use the sethost command to choose a host to recover

<<output snipped>>

amrecover> extract

Extracting files using tape drive chg-disk on host TESTBED001.
The following tapes are needed: DailySet1-10

Restoring files into directory /etc/amanda
Continue [?/Y/n]? y

Extracting files using tape drive chg-disk on host TESTBED001.
Load tape DailySet1-10 now
Continue [?/Y/n/s/t]? y
tar: ./testfile2.txt: Not found in archive
tar: Error exit delayed from previous errors
Extractor child exited with status 2
amrecover>


I left the beginning of the amrecover command in this post because it doesn't look like it belongs, by specifying the host using sethost afterward seems to work...

dustin
June 14th, 2007, 08:59 AM
I was using DailySet1-10:1 in the settape command because this was listed in the history output:

201- 2007-06-14-09-44-19 2 DailySet1-10:1

OK, that was the segfault problem -- settape should actually be given the tape device (despite the name).

I'll try to take a look at the new error in a bit.

ddenton
June 14th, 2007, 01:30 PM
Could it have to do with the GPG errors in the emails from the amanda server from each amdump?
I know you said before that they were warnings, but thought I'd ask, just in case.

? gpg: failed to create temporary file `/var/lib/amanda/.gnupg/.#lk0xa67188.TESTBED002.6118': No such file or directory ? gpg: keyblock resource `/var/lib/amanda/.gnupg/pubring.gpg': general error
| Total bytes written: 20480 (20KiB, ?/s)
? gpg: can't create `/var/lib/amanda/.gnupg/random_seed': No such file or directory

ddenton
June 18th, 2007, 11:28 AM
Dustin,

Just wondering if you had been able to find anything new about that error?

No progress here. I keep getting the same error.

dustin
June 18th, 2007, 11:41 AM
Sorry -- I thought you had figured it out with your second-to-last post. It's very likely your GPG problems are the reason that the dumps aren't complete.

It looks like the permissions are wrong on your GPG configuration. Check the configuration, look through some of the encryption material on the wiki, and try to run parts of it manually.

ddenton
June 18th, 2007, 01:42 PM
Ok, not getting the strange GPG errors anymore, but still failing, but I did find a debug log that may shed some light.

>>
security_getdriver(name=bsdtcp) returns 0x996140
security_handleinit(handle=0x8786b50, driver=0x996140 (BSDTCP))
security_streaminit(stream=0x87952f0, driver=0x996140 (BSDTCP))
security_streaminit(stream=0x879d328, driver=0x996140 (BSDTCP))
amidxtaped_streams[0].fd = 0x879d328
security_streaminit(stream=0x87a5360, driver=0x996140 (BSDTCP))
amidxtaped_streams[1].fd = 0x87a5360
security_close(handle=0x8786b50, driver=0x996140 (BSDTCP))
security_stream_close(0x87952f0)
Exec'ing /bin/tar with arguments:
tar
--numeric-owner
-xpGvf
-
./testfile3.txt
security_stream_seterr(0x87a5360, EOF)
security_stream_close(0x87a5360)
security_stream_seterr(0x879d328, EOF)
security_stream_close(0x879d328)
<<

From this log, it looks like the file was in the process of extracting the file and something happened to the tcp stream. The was never extracted.

tar: ./testfile3.txt: Not found in archive
tar: Error exit delayed from previous errors
Extractor child exited with status 2

This is the end of the error code from the extract. I'm at a loss, because this error doesn't really say a file or process that may be at fault...

dustin
June 18th, 2007, 02:45 PM
How did the GPG errors disappear? Are you restoring from a dump after you fixed that, or one of the old dumps?

Is testfile3.txt in the dump file you're restoring from? What do the files in your vtape directories look like? Have you tried manually untarring them to see what's in them?

ddenton
June 19th, 2007, 10:30 AM
The only thing I did to resolve the GPG errors is temporarily change the perms on /var/lib/amanda/.gnupg to 777. After that, I got an error saying the perms on .gnupg were dangerous, so I changes it back to 750 and while the "dangerous permissions" message still shows up in the backup email alerts, the error for pubring.gpg is gone. Strange.

For my testing, I took a brand new backup with testfile3.txt tried restoring from that, resulting in the same error.

Here's a list of the files in /space/vtapes/DailySet1/slots/slot16:

-rw------- 1 amandabackup disk 10 Jun 18 16:19 00000-DailySet1-16
-rw------- 1 amandabackup disk 32768 Jun 18 16:19 00000.DailySet1-16
-rw------- 1 amandabackup disk 10 Jun 18 16:19 00001-TESTBED002.mydomain.com
-rw------- 1 amandabackup disk 65536 Jun 18 16:19 00001.TESTBED002.mydomain.com
-rw------- 1 amandabackup disk 10 Jun 18 16:19 00002-TAPEEND
-rw------- 1 amandabackup disk 32768 Jun 18 16:19 00002.TAPEEND

I've tried untarring the 3 files that had any size to them, and tar won't open them.

I'm going to try and disable encryption, but can you tell me if any of this looks awry?

ddenton
June 19th, 2007, 11:10 AM
Finally!

I disabled encryption by editing the line for the client in the disklist file and changing it from encrypt-simple to root-tar, and the restore worked.

This leaves me wondering why the encryption wasn't working, but atleast it's working. I'l sure I'll have more questions, but thanks Dustin for your help. It has been greatly appreciated...

paddy
June 19th, 2007, 11:23 AM
Try setting file-pad to "false" in the tape type definition (http://wiki.zmanda.com/index.php/Amanda.conf#TAPETYPE_SECTION)

Paddy

ddenton
June 19th, 2007, 12:02 PM
I added it to the HARDDISK tape type and changed the dumptype back in the disklist and I get the same error as before.

tar: ./testfile4.txt: Not found in archive
tar: Error exit delayed from previous errors
Extractor child exited with status 2

ktill
June 19th, 2007, 02:08 PM
Hi,

did you obtain the program amcryptsimple from this document,
http://amanda.zmanda.com/quick-backup-setup.html?

amcryptsimple is rather straight forward. Couple points to be aware of:

1) amcryptsimple will search for the gpg program in the following directories: /usr/local/bin:/usr/bin:/usr/sbin:/bin:/sbin

2) make sure /var/lib/amandabackup/.am_passphrase can be found on the client as well as the server

3) make sure /var/lib/amandabackup/.am_passphrase is owned by amandabackup:disk and mode 700

4) do not switch dumptype (i.e. from encrypt-simple to root-tar, or vice versa ) between full and incremental dump.

5) mkdir /var/lib/amandabackup/.gnupg so that gpg can place its temporary files

6) Amanda dump file header should indicate amcryptsimple program was used. For example:

AMANDA: FILE 20051215 boston.zmanda.com /usr/tmp/gpa2 lev 0 comp N program /bin/gtar crypt enc client_encrypt /usr/sbin/amcryptsimple client_decrypt_option -d
To restore, position tape at start of file and run:
dd if=<tape> bs=32k skip=1 | /usr/sbin/amcryptsimple -d | /bin/gtar -f...

ktill
June 19th, 2007, 02:19 PM
correction, path should be /var/lib/amanda/ (instead of /var/lib/amandabackup/)

>2) make sure /var/lib/amandabackup/.am_passphrase can be found on the client as well as the server