Results 1 to 7 of 7

Thread: Problem restoring from encrypted backup.

  1. #1
    Join Date
    Mar 2011
    Posts
    8

    Default Problem restoring from encrypted backup.

    Background:

    I have 2 environments at separate locations running AMANDA 3.2.2 on CentOS 5.5.
    Backups are encrypted via amcrypt-ossl

    At the datacenter I have a backup run that produces a full backup to 1 tape. I need to take this tape to the office and be able to perform a restore for disaster recovery testing. (Offisite backup)

    I have two AMANDA jobs running at the office, 1 for standard backups and 1 for disaster recovery restore tests. The normal backup and restore job runs fine and likewise at the datacenter I can backup and restore from the same host no problem.

    For simplicity at this point I copied the /etc/amanda/offsite-job directory to the office, so AMANDA should have all the info it needs to get to the data.

    The configurations (.am_passphrase) are identical. The only difference is in the datacenter I have a changer (Dell PV-124T) and at the office I have a simple SCSI single tape drive.

    I get errors however attempting to restore from the encrypted offsite tape.


    Code:
    amrecover> extract
    
    Extracting files using tape drive tape:/dev/st0 on host localhost.
    The following tapes are needed: OFFSITE
    
    Extracting files using tape drive tape:/dev/st0 on host localhost.
    Load tape OFFSITE now
    Continue [?/Y/n/s/d]? Y
    
    Restoring files into directory /var/log/amanda/client/offsite
    All existing files in /var/log/amanda/client/offsite can be deleted
    Continue [?/Y/n]? 
    /usr/sbin/amcrypt-ossl exited with status 1
    Error writing to fd 8: Broken pipe
    /usr/bin/gzip exited with status 1
    
    tar: This does not look like a tar archive
    tar: ./home/user/file.txt: Not found in archive
    tar: Error exit delayed from previous errors
    Extractor child exited with status 2
    output from amrecover.xx.debug
    Code:
    Wed Mar 30 18:09:06 2011: amrecover: user command: 'extract'
    Wed Mar 30 18:09:06 2011: amrecover: append_to_tapelist(tapelist=(nil), label='OFFSITE', file=-1, partnum=-1,  isafile=0)
    Wed Mar 30 18:09:06 2011: amrecover: append_to_tapelist(tapelist=0x99b13a8, label='OFFSITE', file=5, partnum=-1,  isafile=0)
    Wed Mar 30 18:09:06 2011: amrecover: append_to_tapelist(tapelist=(nil), label='OFFSITE', file=-1, partnum=-1,  isafile=0)
    Wed Mar 30 18:09:06 2011: amrecover: append_to_tapelist(tapelist=0x99b13a8, label='OFFSITE', file=5, partnum=-1,  isafile=0)
    Wed Mar 30 18:09:06 2011: amrecover: Requesting tape OFFSITE from user
    Wed Mar 30 18:09:07 2011: amrecover: User prompt: 'Continue [?/Y/n/s/d]? '; response: 'Y'
    Wed Mar 30 18:09:07 2011: amrecover: security_getdriver(name=bsd) returns 0xce91c0
    Wed Mar 30 18:09:07 2011: amrecover: security_handleinit(handle=0x99b22e0, driver=0xce91c0 (BSD))
    Wed Mar 30 18:09:07 2011: amrecover: dgram_send_addr(addr=0x99b2300, dgram=0xcf1b44)
    Wed Mar 30 18:09:07 2011: amrecover: (sockaddr_in *)0x99b2300 = { 2, 10080, 127.0.0.1 }
    Wed Mar 30 18:09:07 2011: amrecover: dgram_send_addr: 0xcf1b44->socket = 3
    Wed Mar 30 18:09:07 2011: amrecover: dgram_recv(dgram=0xcf1b44, timeout=0, fromaddr=0xd01b30)
    Wed Mar 30 18:09:07 2011: amrecover: (sockaddr_in *)0xd01b30 = { 2, 10080, 127.0.0.1 }
    Wed Mar 30 18:09:07 2011: amrecover: dgram_recv(dgram=0xcf1b44, timeout=0, fromaddr=0xd01b30)
    Wed Mar 30 18:09:07 2011: amrecover: (sockaddr_in *)0xd01b30 = { 2, 10080, 127.0.0.1 }
    Wed Mar 30 18:09:07 2011: amrecover: dgram_send_addr(addr=0x99b2300, dgram=0xcf1b44)
    Wed Mar 30 18:09:07 2011: amrecover: (sockaddr_in *)0x99b2300 = { 2, 10080, 127.0.0.1 }
    Wed Mar 30 18:09:07 2011: amrecover: dgram_send_addr: 0xcf1b44->socket = 3
    Wed Mar 30 18:09:07 2011: amrecover: security_streaminit(stream=0x99c2cb8, driver=0xce91c0 (BSD))
    Wed Mar 30 18:09:07 2011: amrecover: make_socket opening socket with family 2
    Wed Mar 30 18:09:07 2011: amrecover: connect_port: Try  port 1024: available - Success
    Wed Mar 30 18:09:07 2011: amrecover: connected to 127.0.0.1.15488
    Wed Mar 30 18:09:07 2011: amrecover: our side is 0.0.0.0.1024
    Wed Mar 30 18:09:07 2011: amrecover: try_socksize: send buffer size is 65536
    Wed Mar 30 18:09:07 2011: amrecover: try_socksize: receive buffer size is 65536
    Wed Mar 30 18:09:07 2011: amrecover: amidxtaped_streams[0].fd = 0x99c2cb8
    Wed Mar 30 18:09:07 2011: amrecover: security_streaminit(stream=0x99cacf0, driver=0xce91c0 (BSD))
    Wed Mar 30 18:09:07 2011: amrecover: make_socket opening socket with family 2
    Wed Mar 30 18:09:07 2011: amrecover: connect_port: Try  port 1024: available - Success
    Wed Mar 30 18:09:07 2011: amrecover: connected to 127.0.0.1.15489
    Wed Mar 30 18:09:07 2011: amrecover: our side is 0.0.0.0.1024
    Wed Mar 30 18:09:07 2011: amrecover: try_socksize: send buffer size is 65536
    Wed Mar 30 18:09:07 2011: amrecover: try_socksize: receive buffer size is 65536
    Wed Mar 30 18:09:07 2011: amrecover: amidxtaped_streams[1].fd = 0x99cacf0
    Wed Mar 30 18:09:07 2011: amrecover: security_close(handle=0x99b22e0, driver=0xce91c0 (BSD))
    Wed Mar 30 18:09:07 2011: amrecover: send_to_tape_server: FEATURES=ffffffff9efefbffffffffff01
    
    Wed Mar 30 18:09:07 2011: amrecover: send_to_tape_server: CONFIG=offsite
    
    Wed Mar 30 18:09:07 2011: amrecover: send_to_tape_server: LABEL=OFFSITE:5
    
    Wed Mar 30 18:09:07 2011: amrecover: send_to_tape_server: FSF=5
    
    Wed Mar 30 18:09:07 2011: amrecover: send_to_tape_server: HEADER
    
    Wed Mar 30 18:09:07 2011: amrecover: send_to_tape_server: DEVICE=tape:/dev/st0
    
    Wed Mar 30 18:09:07 2011: amrecover: send_to_tape_server: HOST=^some.host.org$
    
    Wed Mar 30 18:09:07 2011: amrecover: send_to_tape_server: DISK=^/$
    
    Wed Mar 30 18:09:07 2011: amrecover: send_to_tape_server: DATESTAMP=20110330084101
    
    Wed Mar 30 18:09:07 2011: amrecover: send_to_tape_server: END
    
    Wed Mar 30 18:10:56 2011: amrecover: read header 32768 => 32768
    Wed Mar 30 18:10:56 2011: amrecover: User prompt: 'Continue [?/Y/n]? '; response: ''
    Wed Mar 30 18:10:56 2011: amrecover: send_to_tape_server: AVAIL-DATAPATH AMANDA
    
    Wed Mar 30 18:10:56 2011: amrecover: get amidxtaped line: USE-DATAPATH AMANDA
    Wed Mar 30 18:10:56 2011: amrecover: Using AMANDA data-path
    Wed Mar 30 18:10:56 2011: amrecover: Exec'ing /bin/tar with arguments:
    Wed Mar 30 18:10:56 2011: amrecover: 	tar
    Wed Mar 30 18:10:56 2011: amrecover: 	--ignore-zeros
    Wed Mar 30 18:10:56 2011: amrecover: 	--numeric-owner
    Wed Mar 30 18:10:56 2011: amrecover: 	-xpGvf
    Wed Mar 30 18:10:56 2011: amrecover: 	-
    Wed Mar 30 18:10:56 2011: amrecover: 	./home/user/file.txt
    Wed Mar 30 18:10:56 2011: amrecover: send_to_tape_server: DATAPATH-OK
    
    Wed Mar 30 18:10:57 2011: amrecover: get amidxtaped line: MESSAGE /usr/sbin/amcrypt-ossl exited with status 1
    Wed Mar 30 18:10:57 2011: amrecover: security_stream_close(0x99cacf0)
    Wed Mar 30 18:10:57 2011: amrecover: get amidxtaped line: MESSAGE Error writing to fd 8: Broken pipe
    Wed Mar 30 18:10:57 2011: amrecover: get amidxtaped line: MESSAGE /usr/bin/gzip exited with status 1
    Wed Mar 30 18:12:39 2011: amrecover: security_stream_close(0x99c2cb8)
    Wed Mar 30 18:16:43 2011: amrecover: pid 21116 finish time Wed Mar 30 18:16:43 2011
    I'm not sure if the problem has to do with the different tape drives. But I can read the tape header fine:
    Code:
    ~# mt -f /dev/st0 fsf 1
    ~# dd if=/dev/st0 bs=32k count=1
    AMANDA: TAPESTART DATE 20110330084101 TAPE OFFSITE
    
    
    0+1 records in
    0+1 records out
    512 bytes (512 B) copied, 0.0667091 seconds, 7.7 kB/s
    Isn't there supposed to be the 'decryption command' in that header?

    Any ideas? Thanks!
    Last edited by lee; March 30th, 2011 at 02:53 PM.

  2. #2
    Join Date
    Nov 2005
    Location
    Canada
    Posts
    1,049

    Default

    What's in the amidxtaped.*.debug file?

    try: amfetchdump offsite some.host.org '^/$' 20110330084101

  3. #3
    Join Date
    Mar 2011
    Posts
    8

    Default

    Thanks for your reply.

    here is the amidxtaped log:
    Code:
    Wed Mar 30 18:09:07 2011: amidxtaped: pid 21831 ruid 505 euid 505 version 3.2.2: start at Wed Mar 30 18:09:07 2011
    Wed Mar 30 18:09:07 2011: amidxtaped: CTL << FEATURES=ffffffff9efefbffffffffff01
    Wed Mar 30 18:09:07 2011: amidxtaped: CTL << CONFIG=offsite
    Wed Mar 30 18:09:07 2011: amidxtaped: CTL << LABEL=OFFSITE:5
    Wed Mar 30 18:09:07 2011: amidxtaped: CTL << FSF=5
    Wed Mar 30 18:09:07 2011: amidxtaped: CTL << HEADER
    Wed Mar 30 18:09:07 2011: amidxtaped: CTL << DEVICE=tape:/dev/st0
    Wed Mar 30 18:09:07 2011: amidxtaped: CTL << HOST=^some.host.com$
    Wed Mar 30 18:09:07 2011: amidxtaped: CTL << DISK=^/$
    Wed Mar 30 18:09:07 2011: amidxtaped: CTL << DATESTAMP=20110330084101
    Wed Mar 30 18:09:07 2011: amidxtaped: CTL << END
    Wed Mar 30 18:09:07 2011: amidxtaped: pid 21831 ruid 505 euid 505 version 3.2.2: rename at Wed Mar 30 18:09:07 2011
    Wed Mar 30 18:09:07 2011: amidxtaped: Amanda::Recovery::Clerk: loading volume 'OFFSITE'
    Wed Mar 30 18:09:07 2011: amidxtaped: find_volume labeled 'OFFSITE'
    Wed Mar 30 18:09:07 2011: amidxtaped: parse_inventory: load slot 0
    Wed Mar 30 18:09:07 2011: amidxtaped: ignoring spurious Amanda::Recovery::Scan abort call
    Wed Mar 30 18:10:56 2011: amidxtaped: Amanda::Recovery::Clerk: successfully located first part for recovery
    Wed Mar 30 18:10:56 2011: amidxtaped: recovering from split dumpfile: date 20110330084101 host some.host.com disk / part 1/UNKNOWN lev 0 comp .gz program /bin/tar crypt enc server_encrypt /usr/sbin/amcrypt-ossl server_decrypt_option -d
    Wed Mar 30 18:10:56 2011: amidxtaped: ..with decompression applied
    Wed Mar 30 18:10:56 2011: amidxtaped: Building type FILE header of 32768-32768 bytes with name='some.host.com' disk='/' dumplevel=0 and blocksize=0
    Wed Mar 30 18:10:56 2011: amidxtaped: CTL << AVAIL-DATAPATH AMANDA
    Wed Mar 30 18:10:56 2011: amidxtaped: CTL >> USE-DATAPATH AMANDA
    Wed Mar 30 18:10:56 2011: amidxtaped: CTL << DATAPATH-OK
    Wed Mar 30 18:10:56 2011: amidxtaped: xfer_start size 9961175056
    Wed Mar 30 18:10:56 2011: amidxtaped: Starting <Xfer@0x9274040 (<XferSourceRecovery@0x9278850> -> <XferFilterProcess@0x926fc10> -> <XferFilterProcess@0x926fc70> -> <XferDestFd@0x9279038>)>
    Wed Mar 30 18:10:56 2011: amidxtaped: Final linkage: <XferSourceRecovery@0x9278850> -(PULL_BUFFER)-> <XferElementGlue@0x9279828> -(READFD)-> <XferFilterProcess@0x926fc10> -(WRITEFD)-> <XferElementGlue@0x92798c0> -(READFD)-> <XferFilterProcess@0x926fc70> -(WRITEFD)-> <XferDestFd@0x9279038>
    Wed Mar 30 18:10:56 2011: amidxtaped: <XferFilterProcess@0x926fc70> spawning: '/usr/bin/gzip' '-dc'
    Wed Mar 30 18:10:56 2011: amidxtaped: <XferFilterProcess@0x926fc10> spawning: '/usr/sbin/amcrypt-ossl' '-d'
    Wed Mar 30 18:10:56 2011: amidxtaped: started xfer; datapath=amanda
    Wed Mar 30 18:10:56 2011: amidxtaped: Amanda::Recovery::Clerk: starting recovery
    Wed Mar 30 18:10:57 2011: amidxtaped: Amanda::Recovery::Clerk: reading file 5 on 'OFFSITE'
    bad magic number
    Wed Mar 30 18:10:57 2011: amidxtaped: <XferFilterProcess@0x926fc10>: process exited with status 1
    
    gzip: stdin: unexpected end of file
    Wed Mar 30 18:10:57 2011: amidxtaped: CTL >> MESSAGE /usr/sbin/amcrypt-ossl exited with status 1
    Wed Mar 30 18:10:57 2011: amidxtaped: Cancelling <Xfer@0x9274040 (<XferSourceRecovery@0x9278850> -> <XferFilterProcess@0x926fc10> -> <XferFilterProcess@0x926fc70> -> <XferDestFd@0x9279038>)>
    Wed Mar 30 18:10:57 2011: amidxtaped: CTL >> MESSAGE Error writing to fd 8: Broken pipe
    Wed Mar 30 18:10:57 2011: amidxtaped: <XferFilterProcess@0x926fc70>: process exited with status 1
    Wed Mar 30 18:10:57 2011: amidxtaped: CTL >> MESSAGE /usr/bin/gzip exited with status 1
    Wed Mar 30 18:10:57 2011: amidxtaped: recovery complete
    Wed Mar 30 18:12:39 2011: amidxtaped: exiting with 0
    Wed Mar 30 18:12:39 2011: amidxtaped: pid 21831 finish time Wed Mar 30 18:12:39 2011


    amfetchdump fails similar to amrecover:
    Code:
    2$ amfetchdump offsite some.host.com '^/$' 20110330084101
    1 volume(s) needed for restoration
    The following volumes are needed: OFFSITE
    Press enter when ready
    
    
    amfetchdump: 5: restoring split dumpfile: date 20110330084101 host some.host.com disk / part 1/UNKNOWN lev 0 comp .gz program /bin/tar crypt enc server_encrypt /usr/sbin/amcrypt-ossl server_decrypt_option -d
    ERROR: Error writing to fd 9: Broken pipe; /usr/sbin/amcrypt-ossl exited with status 1; /usr/bin/gzip exited with status 1

    I am about to see if I can restore from a non-encrypted tape across the sites but I'm not going to the datacenter until next week.
    Last edited by lee; March 31st, 2011 at 08:21 AM.

  4. #4
    Join Date
    Nov 2005
    Location
    Canada
    Posts
    1,049

    Default

    restore the raw data with amfetchdump -l

    then pipe the result to: | /usr/sbin/amcrypt-ossl -d > data.gz
    If it fail, try to pipe it to: | openssl enc -d "-aes-256-cbc" -nopad -salt -pass fd:3 3< ~/.am_passphrase > data.gz

  5. #5
    Join Date
    Mar 2011
    Posts
    8

    Default

    Thanks again, I hope I did this right....

    ~$ amfetchdump -l offsite some.host.com '^/$' 20110330084101

    That appears to have worked, no errors. I got a 9GB file:
    some.host.com._.20110330084101.0

    I verified the data file retrieved from tape matches the size from the amanda report.

    Then I pipe that file through the amcrypt-ossl script?
    cat some.host.com._.20110330084101.0 | /usr/sbin/amcrypt-ossl -d > pweb1.gz

    Which gives:
    bad magic number

    I keep seeing that error "bad magic number" coming up. I imagine it has to do with openssl.

    If I use the openssl command directly I get the same result:

    ~$ cat some.host.com._.20110330084101.0| openssl enc -d "-aes-256-cbc" -nopad -salt -pass fd:3 3< .am_passphrase > data2.gz
    bad magic number

    One last try using openssl only:
    $ openssl enc -d "-aes-256-cbc" -nopad -salt -in some.host.com._.20110330084101.0 -out data3.gz
    enter aes-256-cbc decryption password:
    bad magic number


    I had similar problems using the aespipe/GnuPG method. I was able to encrypt and decrypt from the same machine but transporting to the other host and decrypting never worked.

  6. #6
    Join Date
    Mar 2011
    Posts
    8

    Default

    I'm not sure if the issue lies in openssl exactly.

    On server1 (Datacenter) I encrypted a zip file with the amanda-openssl wrapper script.

    server1:~$ cat somefile.zip | /usr/sbin/amcryot-ossl > enc_data

    I scp'd that file to the office and tried to decrypt:

    office1:~$ cat enc_data | /usr/sbin/amcrypt-ossl -d > dec.zip

    And that worked!

    Is it possible the data is being corrupted via the transfer from tape?

    I used amfetchdump to retrieve a backup from tape on the amanda server at the datacenter.

    I scp'd that file to the office, piped it through amcrypt-ossl. gunzipped it, and untarred it no problems! I can get my data!

    Could this be corruption? Or something else like tape drive settings?
    Last edited by lee; April 1st, 2011 at 12:34 PM.

  7. #7
    Join Date
    Mar 2011
    Posts
    8

    Default Solved.

    So I figured it out!

    This is a little embarrassing but the problem was the block size setting on the tape drive.

    I noticed the datacenter tape drive reported a 512 byte block size.

    The tape drive at the office was set to 0.

    Ran this command and I was able to get to my data!
    ~$ mt -f /dev/st0 setblk 512

    Thanks for the help martineau, I didn't know about amfetchdump... Very useful!

Posting Permissions

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