Results 1 to 10 of 10

Thread: amrecover error -- Got no header and data from server

  1. #1
    Join Date
    Jan 2010
    Location
    Missoula, MT
    Posts
    9

    Default amrecover error -- Got no header and data from server

    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

  2. #2
    Join Date
    Jan 2010
    Location
    Missoula, MT
    Posts
    9

    Default

    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

  3. #3
    Join Date
    Aug 2008
    Location
    Sunnyvale, CA
    Posts
    306

    Default

    Quote Originally Posted by Jonathan.Neff View Post
    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

  4. #4
    Join Date
    Jan 2010
    Location
    Missoula, MT
    Posts
    9

    Default

    Quote Originally Posted by pyeatman View Post
    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

  5. #5
    Join Date
    Aug 2008
    Location
    Sunnyvale, CA
    Posts
    306

    Default

    Quote Originally Posted by Jonathan.Neff View Post
    <...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

  6. #6
    Join Date
    Jan 2010
    Location
    Missoula, MT
    Posts
    9

    Default

    Quote Originally Posted by pyeatman View Post
    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
    Attached Files Attached Files

  7. #7
    Join Date
    Aug 2008
    Location
    Sunnyvale, CA
    Posts
    306

    Default

    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

  8. #8
    Join Date
    Jan 2010
    Location
    Missoula, MT
    Posts
    9

    Default

    Quote Originally Posted by pyeatman View Post
    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

  9. #9
    Join Date
    Jan 2010
    Location
    Missoula, MT
    Posts
    9

    Default

    Quote Originally Posted by Jonathan.Neff View Post
    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

  10. #10
    Join Date
    Aug 2008
    Location
    Sunnyvale, CA
    Posts
    306

    Default

    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

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •