PDA

View Full Version : amrecover error -- Got no header and data from server



Jonathan.Neff
June 1st, 2012, 11:59 AM
Hi,

I'm running Amanda Server 3.3.1 (recently upgraded from 3.3.0) on Debian 6.0. It's a new installation to replace an old 2.4.5 installation on other hardware, but the project got backburnered the last few months. The 3.3 installation has been backing up one of our servers regularly for the last couple of months and we _were_ able to recover with amrecover, as needed. Howerver, after upgrading from 3.3.0 to 3.3.1 this week, I can no longer amrecover successfully -- it may be a coincidence this week; it may be that amrecover has been broken for some time.

We're using virtual tapes and we're running amrecover on the amanda server. After loading the requested tape, amrecover errors with "Got no header and data from server, check in amidxtaped.*.debug and amandad.*.debug files on server"


I've gone through the amidxtaped and amandad logs, but I don't see any realy problem. I'm able to untar the amanda dumps in the slot volumes directly, pulled from dd -- so they seem intact.

Below is the amrecover output, and log output from amidxtaped, amindexd, and amrecover (having to split it up into post replies, due to size -- rather than using pastebin).

Any advice would be appreciated.
Thanks,
Jonathan




amrecover> setdate 2012-05-24
200 Working date set to 2012-05-24.
amrecover> sethost inovativ
200 Dump host set to inovativ.
amrecover> setdisk /var
200 Disk set to /var.
amrecover> add tmp
Added dir /tmp/ at date 2012-05-24-01-13-01
amrecover> extract

Extracting files using tape drive changer on host localhost.
The following tapes are needed: VTAPE4

Extracting files using tape drive changer on host localhost.
Load tape VTAPE4 now
Continue [?/Y/n/s/d]?
Got no header and data from server, check in amidxtaped.*.debug and amandad.*.debug files on server






Thu May 31 14:59:51 2012: thd-0x1ceb6f0: amidxtaped: pid 26888 ruid 1001 euid 1001 version 3.3.1: start at Thu May 31 14:59:51 2012
Thu May 31 14:59:51 2012: thd-0x1ceb6f0: amidxtaped: CTL << FEATURES=ffffffff9efefbffffffffff1f
Thu May 31 14:59:51 2012: thd-0x1ceb6f0: amidxtaped: CTL << CONFIG=mwdaily1
Thu May 31 14:59:51 2012: thd-0x1ceb6f0: amidxtaped: CTL << LABEL=VTAPE6:2
Thu May 31 14:59:51 2012: thd-0x1ceb6f0: amidxtaped: CTL << FSF=2
Thu May 31 14:59:51 2012: thd-0x1ceb6f0: amidxtaped: CTL << HEADER
Thu May 31 14:59:51 2012: thd-0x1ceb6f0: amidxtaped: CTL << DEVICE=chg-disk
Thu May 31 14:59:51 2012: thd-0x1ceb6f0: amidxtaped: CTL << HOST=^inovativ$
Thu May 31 14:59:51 2012: thd-0x1ceb6f0: amidxtaped: CTL << DISK=^/etc$
Thu May 31 14:59:51 2012: thd-0x1ceb6f0: amidxtaped: CTL << DATESTAMP=20120531011301
Thu May 31 14:59:51 2012: thd-0x1ceb6f0: amidxtaped: CTL << END
Thu May 31 14:59:51 2012: thd-0x1ceb6f0: amidxtaped: pid 26888 ruid 1001 euid 1001 version 3.3.1: rename at Thu May 31 14:59:51 2012
Thu May 31 14:59:51 2012: thd-0x1ceb6f0: amidxtaped: Amanda::Recovery::Clerk: loading volume 'VTAPE6'
Thu May 31 14:59:51 2012: thd-0x1ceb6f0: amidxtaped: find_volume labeled 'VTAPE6'
Thu May 31 14:59:51 2012: thd-0x1ceb6f0: amidxtaped: parse_inventory: load slot 6 with label 'VTAPE6'
Thu May 31 14:59:51 2012: thd-0x1ceb6f0: amidxtaped: ignoring spurious Amanda::Recovery::Scan abort call
Thu May 31 14:59:51 2012: thd-0x1ceb6f0: amidxtaped: Amanda::Recovery::Clerk: successfully located first part for recovery
Thu May 31 14:59:51 2012: thd-0x1ceb6f0: amidxtaped: recovering from split dumpfile: date 20120531011301 host inovativ disk /etc part 1/UNKNOWN lev 0 comp .gz program /bin/tar
Thu May 31 14:59:51 2012: thd-0x1ceb6f0: amidxtaped: ..with decompression applied





Thu May 31 14:59:02 2012: thd-0x2416af0: amindexd: pid 26880 ruid 1001 euid 1001 version 3.3.1: start at Thu May 31 14:59:02 2012
Thu May 31 14:59:02 2012: thd-0x2416af0: amindexd: version 3.3.1
Thu May 31 14:59:02 2012: thd-0x2416af0: amindexd: < 220 backup1 AMANDA index server (3.3.1) ready.
Thu May 31 14:59:02 2012: thd-0x2416af0: amindexd: > FEATURES ffffffff9efefbffffffffff1f
Thu May 31 14:59:02 2012: thd-0x2416af0: amindexd: < 200 FEATURES ffffffff9efefbffffffffff1f
Thu May 31 14:59:02 2012: thd-0x2416af0: amindexd: > DATE 2012-05-31
Thu May 31 14:59:02 2012: thd-0x2416af0: amindexd: < 200 Working date set to 2012-05-31.
Thu May 31 14:59:02 2012: thd-0x2416af0: amindexd: > SCNF mwdaily1
Thu May 31 14:59:02 2012: thd-0x2416af0: amindexd: pid 26880 ruid 1001 euid 1001 version 3.3.1: rename at Thu May 31 14:59:02 2012
Thu May 31 14:59:02 2012: thd-0x2416af0: amindexd: < 200 Config set to mwdaily1.
Thu May 31 14:59:02 2012: thd-0x2416af0: amindexd: > HOST backup1
Thu May 31 14:59:02 2012: thd-0x2416af0: amindexd: < 501 Host backup1 is not in your disklist.
Thu May 31 14:59:02 2012: thd-0x2416af0: amindexd: > HOST backup1.modwest.com
Thu May 31 14:59:02 2012: thd-0x2416af0: amindexd: < 501 Host backup1.modwest.com is not in your disklist.
Thu May 31 14:59:02 2012: thd-0x2416af0: amindexd: > HOST backup1
Thu May 31 14:59:02 2012: thd-0x2416af0: amindexd: < 501 Host backup1 is not in your disklist.
Thu May 31 14:59:02 2012: thd-0x2416af0: amindexd: > HOST backup1.modwest.com
Thu May 31 14:59:02 2012: thd-0x2416af0: amindexd: < 501 Host backup1.modwest.com is not in your disklist.
Thu May 31 14:59:09 2012: thd-0x2416af0: amindexd: > HOST inovativ
Thu May 31 14:59:09 2012: thd-0x2416af0: amindexd: < 200 Dump host set to inovativ.
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: > DISK /etc
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: no recovery limit found; allowing access
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: append_to_tapelist(tapelist=(nil), label='VTAPE6', file=2, partnum=1, isafile=0)
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: - 2012-05-31-01-13-01 0 VTAPE6 2 1 1
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: append_to_tapelist(tapelist=(nil), label='VTAPE5', file=2, partnum=1, isafile=0)
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: - 2012-05-25-01-13-01 0 VTAPE5 2 1 1
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: append_to_tapelist(tapelist=(nil), label='VTAPE4', file=3, partnum=1, isafile=0)
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: - 2012-05-24-01-13-01 1 VTAPE4 3 1 1
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: append_to_tapelist(tapelist=(nil), label='VTAPE3', file=2, partnum=1, isafile=0)
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: - 2012-05-16-01-13-01 0 VTAPE3 2 1 1
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: append_to_tapelist(tapelist=(nil), label='VTAPE2', file=2, partnum=1, isafile=0)
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: - 2012-05-11-01-13-01 0 VTAPE2 2 1 1
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: append_to_tapelist(tapelist=(nil), label='VTAPE15', file=3, partnum=1, isafile=0)
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: - 2012-05-10-01-13-01 1 VTAPE15 3 1 1
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: append_to_tapelist(tapelist=(nil), label='VTAPE14', file=2, partnum=1, isafile=0)
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: - 2012-05-04-01-13-01 0 VTAPE14 2 1 1
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: append_to_tapelist(tapelist=(nil), label='VTAPE13', file=2, partnum=1, isafile=0)
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: - 2012-05-03-01-13-01 0 VTAPE13 2 1 1
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: append_to_tapelist(tapelist=(nil), label='VTAPE12', file=3, partnum=1, isafile=0)
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: - 2012-05-01-01-13-01 1 VTAPE12 3 1 1
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: append_to_tapelist(tapelist=(nil), label='VTAPE11', file=2, partnum=1, isafile=0)
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: - 2012-04-27-01-13-01 0 VTAPE11 2 1 1
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: append_to_tapelist(tapelist=(nil), label='VTAPE10', file=2, partnum=1, isafile=0)
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: - 2012-04-26-01-13-01 0 VTAPE10 2 1 1
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: append_to_tapelist(tapelist=(nil), label='VTAPE1', file=2, partnum=1, isafile=0)
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: - 2012-04-24-01-13-02 0 VTAPE1 2 1 1
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: append_to_tapelist(tapelist=(nil), label='VTAPE9', file=2, partnum=1, isafile=0)
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: - 2012-04-23-01-13-01 0 VTAPE9 2 1 1
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: append_to_tapelist(tapelist=(nil), label='VTAPE8', file=2, partnum=1, isafile=0)
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: - 2012-04-21-01-13-01 0 VTAPE8 2 1 1
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: append_to_tapelist(tapelist=(nil), label='VTAPE7', file=2, partnum=1, isafile=0)
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: - 2012-04-17-01-13-01 0 VTAPE7 2 1 1
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: < 200 Disk set to /etc.
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: > OISD /
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: Spawning "/bin/gzip /bin/gzip -dc /var/amanda/mwdaily1/index/inovativ/_etc/20120531011301_0.gz" in pipeline
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: Spawning "/usr/bin/sort /usr/bin/sort" in pipeline
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: f /var/amanda/mwdaily1/index/inovativ/_etc/20120531011301_0
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: < 200 "/" is a valid directory
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: > OLSD /
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: < 200- Opaque list of /
Thu May 31 14:59:16 2012: thd-0x2416af0: amindexd: < 200 Opaque list of /
Thu May 31 14:59:17 2012: thd-0x2416af0: amindexd: > DLE
Thu May 31 14:59:17 2012: thd-0x2416af0: amindexd: < 200 "<dle>\n <program>GNUTAR</program>\n <disk>/etc</disk>\n <auth>BSDTCP</auth>\n <compress>FAST</compress>\n <record>YES</record>\n <index>YES</index>\n <datapath>AMANDA</datapath>\n <exclude>\n <list>/etc/amanda/exclude.gtar</list>\n </exclude>\n</dle>\n"
Thu May 31 14:59:43 2012: thd-0x2416af0: amindexd: > ORLD /apt
Thu May 31 14:59:43 2012: thd-0x2416af0: amindexd: < 200- Opaque list of /apt
Thu May 31 14:59:43 2012: thd-0x2416af0: amindexd: < 200 Opaque list of /apt
Thu May 31 14:59:46 2012: thd-0x2416af0: amindexd: > TAPE
Thu May 31 14:59:46 2012: thd-0x2416af0: amindexd: tapedev_is amrecover_changer: chg-disk
Thu May 31 14:59:46 2012: thd-0x2416af0: amindexd: < 200 chg-disk
Thu May 31 15:05:51 2012: thd-0x2416af0: amindexd: > QUIT
Thu May 31 15:05:51 2012: thd-0x2416af0: amindexd: removing index file: /var/amanda/mwdaily1/index/inovativ/_etc/20120531011301_0
Thu May 31 15:05:51 2012: thd-0x2416af0: amindexd: < 200 Good bye.
Thu May 31 15:05:51 2012: thd-0x2416af0: amindexd: pid 26880 finish time Thu May 31 15:05:51 2012

Jonathan.Neff
June 1st, 2012, 11:59 AM
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: pid 26878 ruid 0 euid 0 version 3.3.1: start at Thu May 31 14:59:02 2012
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: config_overrides: conf mwdaily1
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: pid 26878 ruid 0 euid 0 version 3.3.1: rename at Thu May 31 14:59:02 2012
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: security_getdriver(name=bsdtcp) returns 0x7f2dd2442380
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: security_handleinit(handle=0x22feb10, driver=0x7f2dd2442380 (BSDTCP))
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: security_streaminit(stream=0x2306260, driver=0x7f2dd2442380 (BSDTCP))
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: connect_port: Skip port 512: owned by exec.
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: connect_port: Skip port 513: owned by login.
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: connect_port: Skip port 514: owned by shell.
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: connect_port: Skip port 515: owned by printer.
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: make_socket opening socket with family 2
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: connect_port: Try port 516: available - Success
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: connected to 127.0.0.1:10080
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: our side is 0.0.0.0:516
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: try_socksize: send buffer size is 65536
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: try_socksize: receive buffer size is 65536
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: tcpm_send_token: data is still flowing
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: security_streaminit(stream=0x230e2c0, driver=0x7f2dd2442380 (BSDTCP))
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: security_close(handle=0x22feb10, driver=0x7f2dd2442380 (BSDTCP))
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: security_stream_close(0x2306260)
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: amrecover: get_line size = 48
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: server_line: 220 backup1 AMANDA index server (3.3.1) ready.
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: get:
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: sending: FEATURES ffffffff9efefbffffffffff1f


Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: amrecover: get_line size = 41
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: server_line: 200 FEATURES ffffffff9efefbffffffffff1f
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: get:
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: sending: DATE 2012-05-31


Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: amrecover: get_line size = 37
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: server_line: 200 Working date set to 2012-05-31.
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: get:
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: sending: SCNF mwdaily1


Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: amrecover: get_line size = 29
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: server_line: 200 Config set to mwdaily1.
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: get:
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: sending: HOST backup1


Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: amrecover: get_line size = 43
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: server_line: 501 Host backup1 is not in your disklist.
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: get:
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: sending: HOST backup1.modwest.com


Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: amrecover: get_line size = 55
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: server_line: 501 Host backup1.modwest.com is not in your disklist.
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: get:
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: sending: HOST backup1


Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: amrecover: get_line size = 43
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: server_line: 501 Host backup1 is not in your disklist.
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: get:
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: sending: HOST backup1.modwest.com


Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: amrecover: get_line size = 55
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: server_line: 501 Host backup1.modwest.com is not in your disklist.
Thu May 31 14:59:02 2012: thd-0x22f41f0: amrecover: get:
Thu May 31 14:59:09 2012: thd-0x22f41f0: amrecover: user command: 'sethost inovativ'
Thu May 31 14:59:09 2012: thd-0x22f41f0: amrecover: sending: HOST inovativ


Thu May 31 14:59:09 2012: thd-0x22f41f0: amrecover: amrecover: get_line size = 32
Thu May 31 14:59:09 2012: thd-0x22f41f0: amrecover: server_line: 200 Dump host set to inovativ.
Thu May 31 14:59:09 2012: thd-0x22f41f0: amrecover: get:
Thu May 31 14:59:16 2012: thd-0x22f41f0: amrecover: user command: 'setdisk /etc'
Thu May 31 14:59:16 2012: thd-0x22f41f0: amrecover: sending: DISK /etc


Thu May 31 14:59:16 2012: thd-0x22f41f0: amrecover: tcpm_send_token: data is still flowing
Thu May 31 14:59:16 2012: thd-0x22f41f0: amrecover: amrecover: get_line size = 23
Thu May 31 14:59:16 2012: thd-0x22f41f0: amrecover: server_line: 200 Disk set to /etc.
Thu May 31 14:59:16 2012: thd-0x22f41f0: amrecover: get:
Thu May 31 14:59:16 2012: thd-0x22f41f0: amrecover: sending: OISD /


Thu May 31 14:59:16 2012: thd-0x22f41f0: amrecover: amrecover: get_line size = 30
Thu May 31 14:59:16 2012: thd-0x22f41f0: amrecover: server_line: 200 "/" is a valid directory
Thu May 31 14:59:16 2012: thd-0x22f41f0: amrecover: get:
Thu May 31 14:59:16 2012: thd-0x22f41f0: amrecover: sending: OLSD /


Thu May 31 14:59:16 2012: thd-0x22f41f0: amrecover: amrecover: get_line size = 23
Thu May 31 14:59:16 2012: thd-0x22f41f0: amrecover: server_line: 200- Opaque list of /
Thu May 31 14:59:16 2012: thd-0x22f41f0: amrecover: get:
Thu May 31 14:59:17 2012: thd-0x22f41f0: amrecover: amrecover: get_line size = 4096
Thu May 31 14:59:17 2012: thd-0x22f41f0: amrecover: server_line: 201- 2012-05-31-01-13-01 0 "VTAPE6:2" 2 /
Thu May 31 14:59:17 2012: thd-0x22f41f0: amrecover: get: 201- 2012-05-31-01-13-01 0 "VTAPE6:2" 2 /.java/
201- 2012-05-31-01-13-01 0 "VTAPE6:2" 2 /.pwd.lock
201- 2012-05-31-01-13-01 0 "VTAPE6:2" 2 /Muttrc
201- 2012-05-31-01-13-01 0 "VTAPE6:2" 2 /Muttrc.d/
201- 2012-05-31-01-13-01 0 "VTAPE6:2" 2 /ODBCDataSources/
201- 2012-05-31-01-13-01 0 "VTAPE6:2" 2 /X11/
201- 2012-05-31-01-13-01 0 "VTAPE6:2" 2 /acpi/
201- 2012-05-31-01-13-01 0 "VTAPE6:2" 2 /adduser.conf
201- 2012-05-31-01-13-01 0 "VTAPE6:2" 2 /adjtime
201- 2012-05-31-01-13-01 0 "VTAPE6:2" 2 /aliases
201- 2012-05-31-01-13-01 0 "VTAPE6:2" 2 /aliases.db
201- 2012-05-31-01-13-01 0 "VTAPE6:2" 2 /alternatives/
201- 2012-05-31-01-13-01 0 "VTAPE6:2" 2 /amanda/
201- 2012-05-31-01-13-01 0 "VTAPE6:2" 2 /amandahosts
...
Thu May 31 14:59:46 2012: thd-0x22f41f0: amrecover: user command: 'extract'
Thu May 31 14:59:46 2012: thd-0x22f41f0: amrecover: sending: TAPE


Thu May 31 14:59:46 2012: thd-0x22f41f0: amrecover: amrecover: get_line size = 14
Thu May 31 14:59:46 2012: thd-0x22f41f0: amrecover: server_line: 200 chg-disk
Thu May 31 14:59:46 2012: thd-0x22f41f0: amrecover: get:
Thu May 31 14:59:46 2012: thd-0x22f41f0: amrecover: append_to_tapelist(tapelist=(nil), label='VTAPE6', file=-1, partnum=-1, isafile=0)
Thu May 31 14:59:46 2012: thd-0x22f41f0: amrecover: append_to_tapelist(tapelist=0x2335b50, label='VTAPE6', file=2, partnum=-1, isafile=0)
Thu May 31 14:59:46 2012: thd-0x22f41f0: amrecover: append_to_tapelist(tapelist=(nil), label='VTAPE6', file=-1, partnum=-1, isafile=0)
Thu May 31 14:59:46 2012: thd-0x22f41f0: amrecover: append_to_tapelist(tapelist=0x2335c30, label='VTAPE6', file=2, partnum=-1, isafile=0)
Thu May 31 14:59:46 2012: thd-0x22f41f0: amrecover: Requesting tape VTAPE6 from user
Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: User prompt: 'Continue [?/Y/n/s/d]? '; response: ''
Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: security_getdriver(name=bsdtcp) returns 0x7f2dd2442380
Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: security_handleinit(handle=0x2338a10, driver=0x7f2dd2442380 (BSDTCP))
Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: security_streaminit(stream=0x2338c00, driver=0x7f2dd2442380 (BSDTCP))
Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: security_streaminit(stream=0x2340c60, driver=0x7f2dd2442380 (BSDTCP))
Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: amidxtaped_streams[0].fd = 0x2340c60
Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: security_streaminit(stream=0x2348cc0, driver=0x7f2dd2442380 (BSDTCP))
Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: amidxtaped_streams[1].fd = 0x2348cc0
Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: security_close(handle=0x2338a10, driver=0x7f2dd2442380 (BSDTCP))
Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: security_stream_close(0x2338c00)
Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: send_to_tape_server: FEATURES=ffffffff9efefbffffffffff1f

Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: send_to_tape_server: CONFIG=mwdaily1

Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: send_to_tape_server: LABEL=VTAPE6:2

Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: send_to_tape_server: FSF=2

Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: send_to_tape_server: HEADER

Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: send_to_tape_server: DEVICE=chg-disk

Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: send_to_tape_server: HOST=^inovativ$

Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: send_to_tape_server: DISK=^/etc$

Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: send_to_tape_server: DATESTAMP=20120531011301

Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: send_to_tape_server: END

Thu May 31 14:59:52 2012: thd-0x22f41f0: amrecover: security_stream_seterr(0x2340c60, EOF)
Thu May 31 14:59:52 2012: thd-0x22f41f0: amrecover: security_stream_seterr(0x2348cc0, EOF)
Thu May 31 14:59:52 2012: thd-0x22f41f0: amrecover: security_stream_close(0x2348cc0)
Thu May 31 14:59:52 2012: thd-0x22f41f0: amrecover: bytes read: 0
Thu May 31 14:59:52 2012: thd-0x22f41f0: amrecover: security_stream_close(0x2340c60)
Thu May 31 15:05:51 2012: thd-0x22f41f0: amrecover: user command: 'exit'
Thu May 31 15:05:51 2012: thd-0x22f41f0: amrecover: sending: QUIT


Thu May 31 15:05:51 2012: thd-0x22f41f0: amrecover: tcpm_send_token: data is still flowing
Thu May 31 15:05:51 2012: thd-0x22f41f0: amrecover: amrecover: get_line size = 15
Thu May 31 15:05:51 2012: thd-0x22f41f0: amrecover: server_line: 200 Good bye.
Thu May 31 15:05:51 2012: thd-0x22f41f0: amrecover: get:
Thu May 31 15:05:51 2012: thd-0x22f41f0: amrecover: security_stream_close(0x230e2c0)
Thu May 31 15:05:51 2012: thd-0x22f41f0: amrecover: pid 26878 finish time Thu May 31 15:05:51 2012

pyeatman
June 2nd, 2012, 09:44 PM
Thu May 31 14:59:51 2012: thd-0x1ceb6f0: amidxtaped: ignoring spurious Amanda::Recovery::Scan abort call
Thu May 31 14:59:51 2012: thd-0x1ceb6f0: amidxtaped: Amanda::Recovery::Clerk: successfully located first part for recovery
Thu May 31 14:59:51 2012: thd-0x1ceb6f0: amidxtaped: recovering from split dumpfile: date 20120531011301 host inovativ disk /etc part 1/UNKNOWN lev 0 comp .gz program /bin/tar
Thu May 31 14:59:51 2012: thd-0x1ceb6f0: amidxtaped: ..with decompression applied



Hi!

I notice that the amidxtaped debug file never formally exits as can be seen for the amindexd and amrecover debug files and which implies the process did not finish properly as in crashed or hung. The amrecover line also says to check the "amandad.*.debug" file. This will be in /var/log/amanda/amandad/. What does this contain?

Paul

Jonathan.Neff
June 4th, 2012, 10:00 AM
Hi!

I notice that the amidxtaped debug file never formally exits as can be seen for the amindexd and amrecover debug files and which implies the process did not finish properly as in crashed or hung. The amrecover line also says to check the "amandad.*.debug" file. This will be in /var/log/amanda/amandad/. What does this contain?

Paul

Hi Paul -- thanks for taking a look.

Here's the amandad log file output for the session.


backup1:/var/log/amanda/amandad# cat amandad.20120531145902.debug
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: pid 26879 ruid 1001 euid 1001 version 3.3.1: start at Thu May 31 14:59:02 2012
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: security_getdriver(name=bsdtcp) returns 0x7f11aa1c3380
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: version 3.3.1
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: build: VERSION="Amanda-3.3.1"
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: BUILT_DATE="Tue Feb 21 10:48:48 PST 2012" BUILT_MACH=""
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: BUILT_REV="4553" BUILT_BRANCH="community_3_3_1"
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: CC="x86_64-linux-gnu-gcc"
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: paths: bindir="/usr/bin" sbindir="/usr/sbin"
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: libexecdir="/usr/libexec"
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: amlibexecdir="/usr/libexec/amanda" mandir="/usr/share/man"
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: AMANDA_TMPDIR="/tmp/amanda"
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: AMANDA_DBGDIR="/var/log/amanda" CONFIG_DIR="/etc/amanda"
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: DEV_PREFIX="/dev/" RDEV_PREFIX="/dev/" DUMP="/sbin/dump"
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: RESTORE="/sbin/restore" VDUMP=UNDEF VRESTORE=UNDEF
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: XFSDUMP="/sbin/xfsdump" XFSRESTORE="/sbin/xfsrestore"
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: VXDUMP=UNDEF VXRESTORE=UNDEF
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: SAMBA_CLIENT="/usr/bin/smbclient" GNUTAR="/bin/tar"
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: COMPRESS_PATH="/bin/gzip" UNCOMPRESS_PATH="/bin/gzip"
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: LPRCMD=UNDEF MAILER=UNDEF
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: listed_incr_dir="/var/lib/amanda/gnutar-lists"
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: defs: DEFAULT_SERVER="localhost" DEFAULT_CONFIG="DailySet1"
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: DEFAULT_TAPE_SERVER="localhost" DEFAULT_TAPE_DEVICE=""
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: NEED_STRSTR AMFLOCK_POSIX AMFLOCK_FLOCK AMFLOCK_LOCKF
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: AMFLOCK_LNLOCK SETPGRP_VOID ASSERTIONS AMANDA_DEBUG_DAYS=4
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: BSD_SECURITY USE_AMANDAHOSTS CLIENT_LOGIN="amandabackup"
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: CHECK_USERID HAVE_GZIP COMPRESS_SUFFIX=".gz"
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: COMPRESS_FAST_OPT="--fast" COMPRESS_BEST_OPT="--best"
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: UNCOMPRESS_OPT="-dc"
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: security_handleinit(handle=0x259a000, driver=0x7f11aa1c3380 (BSDTCP))
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: security_streaminit(stream=0x259a480, driver=0x7f11aa1c3380 (BSDTCP))
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: authenticated peer name is 'localhost'
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: accept recv REQ pkt:
<<<<<
SERVICE amindexd
OPTIONS features=ffffffff9efefbffffffffff1f;auth=bsdtcp;
>>>>>
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: creating new service: amindexd
OPTIONS features=ffffffff9efefbffffffffff1f;auth=bsdtcp;

Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: state_machine: 0x25a2690 entering
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: state_machine: 0x25a2690 curstate=s_sendack action=A_START
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: sending ACK pkt:
<<<<<
>>>>>
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: tcpm_send_token: data is still flowing
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: state_machine: 0x25a2690 curstate=s_sendack returned A_PENDING (nextstate=s_repwait)
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: state_machine: 0x25a2690 leaving (A_PENDING)
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: state_machine: 0x25a2690 entering
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: state_machine: 0x25a2690 curstate=s_repwait action=A_RECVREP
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: state_machine: 0x25a2690 curstate=s_repwait returned A_PENDING (nextstate=s_repwait)
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: state_machine: 0x25a2690 leaving (A_PENDING)
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: state_machine: 0x25a2690 entering
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: state_machine: 0x25a2690 curstate=s_repwait action=A_RECVREP
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: state_machine: 0x25a2690 curstate=s_repwait returned A_CONTINUE (nextstate=s_processrep)
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: state_machine: 0x25a2690 curstate=s_processrep action=A_RECVREP
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: security_streaminit(stream=0x25b31f0, driver=0x7f11aa1c3380 (BSDTCP))
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: state_machine: 0x25a2690 curstate=s_processrep returned A_CONTINUE (nextstate=s_sendrep)
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: state_machine: 0x25a2690 curstate=s_sendrep action=A_RECVREP
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: sending REP pkt:
<<<<<
CONNECT MESG 499999

>>>>>
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: state_machine: 0x25a2690 curstate=s_sendrep returned A_PENDING (nextstate=s_ackwait)
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: state_machine: 0x25a2690 leaving (A_PENDING)
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: received ACK pkt:
<<<<<
>>>>>
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: state_machine: 0x25a2690 entering
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: state_machine: 0x25a2690 curstate=s_ackwait action=A_RECVPKT
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: received ACK, now opening streams
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: opening security stream for fd 50
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: at end of s_ackwait, npipes is 1
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: security_close(handle=0x259a000, driver=0x7f11aa1c3380 (BSDTCP))
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: security_stream_close(0x259a480)
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: state_machine: 0x25a2690 curstate=s_ackwait returned A_PENDING (nextstate=s_ackwait)
Thu May 31 14:59:02 2012: thd-0x258fb30: amandad: state_machine: 0x25a2690 leaving (A_PENDING)
Thu May 31 14:59:16 2012: thd-0x258fb30: amandad: stream_read_callback: data is still flowing
Thu May 31 14:59:43 2012: thd-0x258fb30: amandad: stream_read_callback: data is still flowing
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: security_handleinit(handle=0x259a560, driver=0x7f11aa1c3380 (BSDTCP))
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: security_streaminit(stream=0x25bb540, driver=0x7f11aa1c3380 (BSDTCP))
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: authenticated peer name is 'localhost'
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: accept recv REQ pkt:
<<<<<
SERVICE amidxtaped
OPTIONS features=ffffffff9efefbffffffffff1f;auth=bsdtcp;
>>>>>
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: creating new service: amidxtaped
OPTIONS features=ffffffff9efefbffffffffff1f;auth=bsdtcp;

Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: state_machine: 0x25c35a0 entering
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: state_machine: 0x25c35a0 curstate=s_sendack action=A_START
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: sending ACK pkt:
<<<<<
>>>>>
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: state_machine: 0x25c35a0 curstate=s_sendack returned A_PENDING (nextstate=s_repwait)
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: state_machine: 0x25c35a0 leaving (A_PENDING)
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: state_machine: 0x25c35a0 entering
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: state_machine: 0x25c35a0 curstate=s_repwait action=A_RECVREP
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: state_machine: 0x25c35a0 curstate=s_repwait returned A_PENDING (nextstate=s_repwait)
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: state_machine: 0x25c35a0 leaving (A_PENDING)
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: state_machine: 0x25c35a0 entering
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: state_machine: 0x25c35a0 curstate=s_repwait action=A_RECVREP
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: state_machine: 0x25c35a0 curstate=s_repwait returned A_CONTINUE (nextstate=s_processrep)
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: state_machine: 0x25c35a0 curstate=s_processrep action=A_RECVREP
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: security_streaminit(stream=0x25d36f0, driver=0x7f11aa1c3380 (BSDTCP))
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: security_streaminit(stream=0x25db750, driver=0x7f11aa1c3380 (BSDTCP))
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: state_machine: 0x25c35a0 curstate=s_processrep returned A_CONTINUE (nextstate=s_sendrep)
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: state_machine: 0x25c35a0 curstate=s_sendrep action=A_RECVREP
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: sending REP pkt:
<<<<<
CONNECT CTL 499998 DATA 499997

>>>>>
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: state_machine: 0x25c35a0 curstate=s_sendrep returned A_PENDING (nextstate=s_ackwait)
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: state_machine: 0x25c35a0 leaving (A_PENDING)
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: received ACK pkt:
<<<<<
>>>>>
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: state_machine: 0x25c35a0 entering
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: state_machine: 0x25c35a0 curstate=s_ackwait action=A_RECVPKT
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: received ACK, now opening streams
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: opening security stream for fd 50
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: opening security stream for fd 51
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: at end of s_ackwait, npipes is 2
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: security_close(handle=0x259a560, driver=0x7f11aa1c3380 (BSDTCP))
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: security_stream_close(0x25bb540)
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: state_machine: 0x25c35a0 curstate=s_ackwait returned A_PENDING (nextstate=s_ackwait)
Thu May 31 14:59:51 2012: thd-0x258fb30: amandad: state_machine: 0x25c35a0 leaving (A_PENDING)
Thu May 31 14:59:52 2012: thd-0x258fb30: amandad: security_stream_close(0x25d36f0)
Thu May 31 14:59:52 2012: thd-0x258fb30: amandad: security_stream_close(0x25db750)
Thu May 31 14:59:52 2012: thd-0x258fb30: amandad: closing service: /usr/libexec/amanda/amidxtaped
Thu May 31 15:05:51 2012: thd-0x258fb30: amandad: stream_read_callback: data is still flowing
Thu May 31 15:05:51 2012: thd-0x258fb30: amandad: security_stream_close(0x25b31f0)
Thu May 31 15:05:51 2012: thd-0x258fb30: amandad: closing service: /usr/libexec/amanda/amindexd
Thu May 31 15:05:51 2012: thd-0x258fb30: amandad: pid 26879 finish time Thu May 31 15:05:51 2012

pyeatman
June 4th, 2012, 10:59 AM
<...snip...>
Thu May 31 14:59:52 2012: thd-0x258fb30: amandad: closing service: /usr/libexec/amanda/amidxtaped
Thu May 31 15:05:51 2012: thd-0x258fb30: amandad: stream_read_callback: data is still flowing
Thu May 31 15:05:51 2012: thd-0x258fb30: amandad: security_stream_close(0x25b31f0)
Thu May 31 15:05:51 2012: thd-0x258fb30: amandad: closing service: /usr/libexec/amanda/amindexd
Thu May 31 15:05:51 2012: thd-0x258fb30: amandad: pid 26879 finish time Thu May 31 15:05:51 2012

Hi Jonathan, I don't see any particular issue in the amandad debug file. I can see were it closes both the amindxtaped and amindexd services. The amindexd debug file shows the QUIT at this exact time and the process cleanly exits. I don't see this in the amidxtaped debug file. Thus, it looks like this process (pid 26888) crashed (versus hung supposing it is not still running). Is this result repeatable? Did any client-side process get started as seen by the creation of a debug file at the time of the restore in /var/log/amanda/client/mwdaily1/?

Paul

Jonathan.Neff
June 4th, 2012, 12:37 PM
Hi Jonathan, I don't see any particular issue in the amandad debug file. I can see were it closes both the amindxtaped and amindexd services. The amindexd debug file shows the QUIT at this exact time and the process cleanly exits. I don't see this in the amidxtaped debug file. Thus, it looks like this process (pid 26888) crashed (versus hung supposing it is not still running). Is this result repeatable? Did any client-side process get started as seen by the creation of a debug file at the time of the restore in /var/log/amanda/client/mwdaily1/?

Paul

Hi Paul,

The amrecover*.debug file is created at /var/log/amanda/client/mwdaily1/ and is about 500K.
There's a lot of repetition to it, so am snipping most of it, leaving the last part here, and attaching the full file to this post.


Thu May 31 14:59:46 2012: thd-0x22f41f0: amrecover: user command: 'extract'
Thu May 31 14:59:46 2012: thd-0x22f41f0: amrecover: sending: TAPE


Thu May 31 14:59:46 2012: thd-0x22f41f0: amrecover: amrecover: get_line size = 14
Thu May 31 14:59:46 2012: thd-0x22f41f0: amrecover: server_line: 200 chg-disk
Thu May 31 14:59:46 2012: thd-0x22f41f0: amrecover: get:
Thu May 31 14:59:46 2012: thd-0x22f41f0: amrecover: append_to_tapelist(tapelist=(nil), label='VTAPE6', file=-1, partnum=-1, isafile=0)
Thu May 31 14:59:46 2012: thd-0x22f41f0: amrecover: append_to_tapelist(tapelist=0x2335b50, label='VTAPE6', file=2, partnum=-1, isafile=0)
Thu May 31 14:59:46 2012: thd-0x22f41f0: amrecover: append_to_tapelist(tapelist=(nil), label='VTAPE6', file=-1, partnum=-1, isafile=0)
Thu May 31 14:59:46 2012: thd-0x22f41f0: amrecover: append_to_tapelist(tapelist=0x2335c30, label='VTAPE6', file=2, partnum=-1, isafile=0)
Thu May 31 14:59:46 2012: thd-0x22f41f0: amrecover: Requesting tape VTAPE6 from user
Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: User prompt: 'Continue [?/Y/n/s/d]? '; response: ''
Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: security_getdriver(name=bsdtcp) returns 0x7f2dd2442380
Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: security_handleinit(handle=0x2338a10, driver=0x7f2dd2442380 (BSDTCP))
Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: security_streaminit(stream=0x2338c00, driver=0x7f2dd2442380 (BSDTCP))
Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: security_streaminit(stream=0x2340c60, driver=0x7f2dd2442380 (BSDTCP))
Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: amidxtaped_streams[0].fd = 0x2340c60
Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: security_streaminit(stream=0x2348cc0, driver=0x7f2dd2442380 (BSDTCP))
Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: amidxtaped_streams[1].fd = 0x2348cc0
Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: security_close(handle=0x2338a10, driver=0x7f2dd2442380 (BSDTCP))
Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: security_stream_close(0x2338c00)
Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: send_to_tape_server: FEATURES=ffffffff9efefbffffffffff1f

Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: send_to_tape_server: CONFIG=mwdaily1

Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: send_to_tape_server: LABEL=VTAPE6:2

Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: send_to_tape_server: FSF=2

Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: send_to_tape_server: HEADER

Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: send_to_tape_server: DEVICE=chg-disk

Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: send_to_tape_server: HOST=^inovativ$

Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: send_to_tape_server: DISK=^/etc$

Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: send_to_tape_server: DATESTAMP=20120531011301

Thu May 31 14:59:51 2012: thd-0x22f41f0: amrecover: send_to_tape_server: END

Thu May 31 14:59:52 2012: thd-0x22f41f0: amrecover: security_stream_seterr(0x2340c60, EOF)
Thu May 31 14:59:52 2012: thd-0x22f41f0: amrecover: security_stream_seterr(0x2348cc0, EOF)
Thu May 31 14:59:52 2012: thd-0x22f41f0: amrecover: security_stream_close(0x2348cc0)
Thu May 31 14:59:52 2012: thd-0x22f41f0: amrecover: bytes read: 0
Thu May 31 14:59:52 2012: thd-0x22f41f0: amrecover: security_stream_close(0x2340c60)
Thu May 31 15:05:51 2012: thd-0x22f41f0: amrecover: user command: 'exit'
Thu May 31 15:05:51 2012: thd-0x22f41f0: amrecover: sending: QUIT
Thu May 31 15:05:51 2012: thd-0x22f41f0: amrecover: tcpm_send_token: data is still flowing
Thu May 31 15:05:51 2012: thd-0x22f41f0: amrecover: amrecover: get_line size = 15
Thu May 31 15:05:51 2012: thd-0x22f41f0: amrecover: server_line: 200 Good bye.
Thu May 31 15:05:51 2012: thd-0x22f41f0: amrecover: get:
Thu May 31 15:05:51 2012: thd-0x22f41f0: amrecover: security_stream_close(0x230e2c0)
Thu May 31 15:05:51 2012: thd-0x22f41f0: amrecover: pid 26878 finish time Thu May 31 15:05:51 2012

pyeatman
June 4th, 2012, 04:34 PM
Thanks, Jonathan.

What I was checking for was whether the Amanda API to read the data was ever started. The data would be read from tape and then streamed via gzip and gpg as appropriate and then to the Amanda API that created the data. For a Linux/UNIX file system backup, this would be amgtar, amsuntar, or amstar. I was wondering if there is a debug file from any of these APIs during the restore. It sounds like there is not.

The only clue of a problem in the amrecover debug file is "amrecover: bytes read: 0" upon which Amanda must issue the "check in amidxtaped.*.debug and amandad.*.debug files on server" message. From checking these files, we see that amidxtaped ends abruptly. I suppose 0 bytes are read because the amindxtaped service does not complete correctly. Does the amidxtaped debug file continue to show an abrupt ending?

I notice in the amidxtaped debug file that it looks like the data on tape is compressed:


Thu May 31 14:59:51 2012: thd-0x1ceb6f0: amidxtaped: recovering from split dumpfile: date 20120531011301 host inovativ disk /etc part 1/UNKNOWN lev 0 comp .gz program /bin/tar
Thu May 31 14:59:51 2012: thd-0x1ceb6f0: amidxtaped: ..with decompression applied


This is also where the file abruptly ends. I'm curious if you run into the same issue when restoring from an uncompressed backup.

Paul

Jonathan.Neff
June 5th, 2012, 10:03 AM
Thanks, Jonathan.

What I was checking for was whether the Amanda API to read the data was ever started. The data would be read from tape and then streamed via gzip and gpg as appropriate and then to the Amanda API that created the data. For a Linux/UNIX file system backup, this would be amgtar, amsuntar, or amstar. I was wondering if there is a debug file from any of these APIs during the restore. It sounds like there is not.

The only clue of a problem in the amrecover debug file is "amrecover: bytes read: 0" upon which Amanda must issue the "check in amidxtaped.*.debug and amandad.*.debug files on server" message. From checking these files, we see that amidxtaped ends abruptly. I suppose 0 bytes are read because the amindxtaped service does not complete correctly. Does the amidxtaped debug file continue to show an abrupt ending?

I notice in the amidxtaped debug file that it looks like the data on tape is compressed:



This is also where the file abruptly ends. I'm curious if you run into the same issue when restoring from an uncompressed backup.

Paul

Interesting -- okay. I should have looked earlier, but I do see amidxtaped segfaulting in kern.log:
May 31 14:59:52 backup1 kernel: [171058.665440] amidxtaped[26888]: segfault at 0 ip 00007f10ecfc8cf2 sp 00007ffffa96d548 error 4 in libc-2.11.3.so[7f10ecf4d000+159000]

I'll try some tests with an uncompressed backup.

Thanks,
Jonathan

Jonathan.Neff
June 5th, 2012, 11:15 AM
Interesting -- okay. I should have looked earlier, but I do see amidxtaped segfaulting in kern.log:
May 31 14:59:52 backup1 kernel: [171058.665440] amidxtaped[26888]: segfault at 0 ip 00007f10ecfc8cf2 sp 00007ffffa96d548 error 4 in libc-2.11.3.so[7f10ecf4d000+159000]

I'll try some tests with an uncompressed backup.

Thanks,
Jonathan


Restoring from an uncompressed backup worked fine, it appears. Any thoughts on what might be happening with regards to compression?

Thanks,
Jonathan


Tue Jun 5 13:09:36 2012: thd-0x1a056f0: amidxtaped: pid 32664 ruid 1001 euid 1001 version 3.3.1: start at Tue Jun 5 13:09:36 2012
Tue Jun 5 13:09:36 2012: thd-0x1a056f0: amidxtaped: CTL << FEATURES=ffffffff9efefbffffffffff1f
Tue Jun 5 13:09:36 2012: thd-0x1a056f0: amidxtaped: CTL << CONFIG=mwdaily1
Tue Jun 5 13:09:36 2012: thd-0x1a056f0: amidxtaped: CTL << LABEL=VTAPE9:3
Tue Jun 5 13:09:36 2012: thd-0x1a056f0: amidxtaped: CTL << FSF=3
Tue Jun 5 13:09:36 2012: thd-0x1a056f0: amidxtaped: CTL << HEADER
Tue Jun 5 13:09:36 2012: thd-0x1a056f0: amidxtaped: CTL << DEVICE=chg-disk
Tue Jun 5 13:09:36 2012: thd-0x1a056f0: amidxtaped: CTL << HOST=^inovativ$
Tue Jun 5 13:09:36 2012: thd-0x1a056f0: amidxtaped: CTL << DISK=^/etc$
Tue Jun 5 13:09:36 2012: thd-0x1a056f0: amidxtaped: CTL << DATESTAMP=20120605130635
Tue Jun 5 13:09:36 2012: thd-0x1a056f0: amidxtaped: CTL << END
Tue Jun 5 13:09:36 2012: thd-0x1a056f0: amidxtaped: pid 32664 ruid 1001 euid 1001 version 3.3.1: rename at Tue Jun 5 13:09:36 2012
Tue Jun 5 13:09:36 2012: thd-0x1a056f0: amidxtaped: Amanda::Recovery::Clerk: loading volume 'VTAPE9'
Tue Jun 5 13:09:36 2012: thd-0x1a056f0: amidxtaped: find_volume labeled 'VTAPE9'
Tue Jun 5 13:09:36 2012: thd-0x1a056f0: amidxtaped: parse_inventory: load slot 9 with label 'VTAPE9'
Tue Jun 5 13:09:36 2012: thd-0x1a056f0: amidxtaped: ignoring spurious Amanda::Recovery::Scan abort call
Tue Jun 5 13:09:36 2012: thd-0x1a056f0: amidxtaped: Amanda::Recovery::Clerk: successfully located first part for recovery
Tue Jun 5 13:09:36 2012: thd-0x1a056f0: amidxtaped: recovering from split dumpfile: date 20120605130635 host inovativ disk /etc part 1/UNKNOWN lev 0 comp N program /bin/tar
Tue Jun 5 13:09:36 2012: thd-0x1a056f0: amidxtaped: Building type FILE header of 32768-32768 bytes with name='inovativ' disk='/etc' dumplevel=0 and blocksize=0
Tue Jun 5 13:09:58 2012: thd-0x1a056f0: amidxtaped: CTL << AVAIL-DATAPATH AMANDA
Tue Jun 5 13:09:58 2012: thd-0x1a056f0: amidxtaped: CTL >> USE-DATAPATH AMANDA
Tue Jun 5 13:09:58 2012: thd-0x1a056f0: amidxtaped: CTL << DATAPATH-OK
Tue Jun 5 13:09:58 2012: thd-0x1a056f0: amidxtaped: Starting <Xfer@0x232aa20 (<XferSourceRecovery@0x2318840> -> <XferDestFd@0x232ac30>)>
Tue Jun 5 13:09:58 2012: thd-0x1a056f0: amidxtaped: Final linkage: <XferSourceRecovery@0x2318840> -(PULL_BUFFER)-> <XferElementGlue@0x2313190> -(WRITEFD)-> <XferDestFd@0x232ac30>
Tue Jun 5 13:09:58 2012: thd-0x1a056f0: amidxtaped: started xfer; datapath=amanda
Tue Jun 5 13:09:58 2012: thd-0x1a056f0: amidxtaped: Amanda::Recovery::Clerk: starting recovery
Tue Jun 5 13:09:58 2012: thd-0x1a056f0: amidxtaped: Amanda::Recovery::Clerk: reading file 3 on 'VTAPE9'
Tue Jun 5 13:09:59 2012: thd-0x232b9b0: amidxtaped: Device file:/amanda_vtapes/vtapes/drive0 error = 'EOF'
Tue Jun 5 13:09:59 2012: thd-0x1a056f0: amidxtaped: Amanda::Recovery::Clerk: done reading file 3 on 'VTAPE9'
Tue Jun 5 13:09:59 2012: thd-0x1a056f0: amidxtaped: recovery complete
Tue Jun 5 13:09:59 2012: thd-0x1a056f0: amidxtaped: exiting with 0
Tue Jun 5 13:09:59 2012: thd-0x1a056f0: amidxtaped: pid 32664 finish time Tue Jun 5 13:09:59 2012

pyeatman
June 5th, 2012, 04:30 PM
That looks better. The debug file shows the process is finishing and exiting normally. That doesn't mean I am understanding why there is an issue when decompression during the restore, however.

One thing I did notice is that you are essentially using your 2.4 config in 3.3. This should be okay as backup shows but possibly you can try using the Amanda API for GNU tar backups (amgtar) in your configuration rather than /bin/tar directly. To do this, your "program" becomes "application" and then you define an application that uses the "amgtar" plugin. Not that I have a particular reason why this would resolve the issue but, while you are getting more up to date, it may also have some impact on this issue as I have not seen it before :p