Encryption Errors:Broken Pipe v2.5

[c-vaughan]

I followed this guide verbatim http://wiki.zmanda.com/index.php/Encryption I am using 2.5 and I get the following error when I try to make a backup.

DISK planner jave /boot
START planner date 20060328
INFO planner Adding new disk jave:/boot.
START driver date 20060328
STATS driver startup time 0.013
FINISH planner date 20060328 time 0.034
START taper datestamp 20060328 label unsensitive01 tape 0
PARTIAL chunker jave /boot 20060328 0 [sec 0.063 kb 1 kps 521.4]
FAIL dumper jave /boot 20060328 0 [data write: Broken pipe]
sendbackup: start [jave:/boot level 0]
sendbackup: info BACKUP=/bin/tar
sendbackup: info RECOVER_CMD=/bin/tar -f... -
sendbackup: info end
PARTIAL chunker jave /boot 20060328 0 [sec 0.071 kb 1 kps 464.7]
FAIL dumper jave /boot 20060328 0 [data write: Broken pipe]
sendbackup: start [jave:/boot level 0]
sendbackup: info BACKUP=/bin/tar
sendbackup: info RECOVER_CMD=/bin/tar -f... -
sendbackup: info end
PARTIAL taper jave /boot 20060328 0 [sec 4.147 kb 64 kps 15.4 {wr: writers 2 rdwait 0.000 wrwait 0.004 filemark 4.142}]
INFO taper tape unsensitive01 kb 64 fm 1 [OK]
FINISH driver date 20060328 time 34.489

Jave is the host.

define dumptype encrypt-fast {
root-tar
program "GNUTAR"
comment "dump with fast client compression and server symmetric encryption"
encrypt server
server_encrypt "/usr/local/sbin/amcrypt"
server_decrypt_option "-d"
}

Anyone have any hints? Thanks for the help. I can make a regular backup with no problems it's just when I use encryption that I get these errors. I tried amcheck and that reports no errors. Server is RHE4 and client is Debian Sarge.

Thanks,

-Chris Vaughan

[ktill]

Hi,

any error on amdump.1 file?

is aespipe, uuencode and gpg installed on the server?

Thanks!

--Kevin Till

[c-vaughan]

Thanks for the hint, I found this error.

Error: gpg key file decryption failed


That could be my problem there.

I'll try it tomorrow.

[c-vaughan]

So it's now encrypting the file but when I try to recover the backup I get errors.

This is the command that I am running:

[root@amanda2 unsensitive]# dd if=/dev/tape bs=32k skip=1 | /usr/local/sbin/amcrypt -d | /bin/gzip -dc | /bin/tar -xf -
1+0 records in
0+0 records out

gzip: stdin: unexpected end of file

Any idea as to how I get this backup off of the tape?

This is the header info I get:

AMANDA: FILE 20060329 manuel /boot lev 1 comp .gz program /bin/tar crypt enc server_encrypt /usr/local/sbin/amcrypt server_decrypt_option -d
To restore, position tape at start of file and run:
dd if=<tape> bs=32k skip=1 | /usr/local/sbin/amcrypt -d | /bin/gzip -dc | /bin/tar -f... -


Thanks,

[ktill]

Hi,

is the tape rewind ?
I think the amdump was not done properly.
Please see if there is any error on amdump.1 or the latest log file in that directory?

Did Amanda send a mail reporting sucess after amdump?

I just tried it on my machine running Amanda 2.5.0 and it works fine.

--Kevin Till
Zmanda

[c-vaughan]

Well it was dumping correctly earlier today and now I'm having errors getting it to dump a new volume. Yes the tape gets rewound everytime, it has a label. It dumps non encrypted files consistently fine.

Here is the amdump file:

GENERATING SCHEDULE:--------DUMP manuel fffffeff9ffeffff07 /boot 20060329 13238 0 1970:1:1:0:0:0 7235 7--------changer: got exit: 0 str: 1 99 1changer_query: changer return was 99 1changer_query: searchable = 0changer_find: looking for NULL changer is searchable = 0changer: opening pipe to: /usr/lib/amanda/chg-manual -slot currentchanger: got exit: 0 str: 1 /dev/tapetaper: wrote label `unsensitive01' date `20060329'driver: result time 10.884 from taper: TAPER-OKdriver: state time 10.884 free kps: 2000 space: 10485760 taper: idle idle-dumpers: 4 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 0 driver-idle: not-idledriver: interface-state time 10.884 if : free 600 if ETH0: free 400 if LOCAL: free 1000driver: hdisk-state time 10.884 hdisk 0: free 10485760 dumpers 0driver: flush size 0driver: started chunker0 pid 3122driver: send-cmd time 10.886 to chunker0: PORT-WRITE 00-00001 /var/tmp/20060329161259/manuel._boot.0 manuel fffffeff9ffeffff07 /boot 0 1970:1:1:0:0:0 1048576 GNUTAR 7328 |;auth=BSD;compress-fast;encrypt-serv-cust=/usr/local/sbin/amcrypt;server-decrypt-option=-d;chunker: pid 3122 executable chunker0 version 2.5.0chunker: try_socksize: receive buffer size is 65536chunker: bind_portrange2: trying port=664chunker: stream_server: waiting for connection: 0.0.0.0.32771driver: result time 10.956 from chunker0: PORT 32771driver: send-cmd time 10.957 to dumper0: PORT-DUMP 00-00001 32771 manuel fffffeff9ffeffff07 /boot NODEVICE 0 1970:1:1:0:0:0 GNUTAR |;auth=BSD;compress-fast;encrypt-serv-cust=/usr/local/sbin/amcrypt;server-decrypt-option=-d;chunker: stream_accept: connection from 127.0.0.1.32772chunker: try_socksize: receive buffer size is 32768dumper: stream_client: connected to 127.0.0.1.32771dumper: stream_client: our side is 0.0.0.0.32772dumper: try_socksize: send buffer size is 65536dumper: bind_portrange2: trying port=633dumper: dgram_bind: socket bound to 0.0.0.0.633dumper: stream_client: connected to 192.168.1.56.58584dumper: stream_client: our side is 0.0.0.0.32773dumper: try_socksize: send buffer size is 65536dumper: try_socksize: receive buffer size is 65536dumper: stream_client: connected to 192.168.1.56.49247dumper: stream_client: our side is 0.0.0.0.32774dumper: try_socksize: send buffer size is 65536dumper: try_socksize: receive buffer size is 65536dumper: kill encrypt commanddriver: state time 11.290 free kps: 967 space: 10478432 taper: idle idle-dumpers: 3 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 0 driver-idle: no-dumpersdriver: interface-state time 11.290 if : free -433 if ETH0: free 400 if LOCAL: free 1000driver: hdisk-state time 11.290 hdisk 0: free 10478432 dumpers 1driver: result time 11.290 from dumper0: FAILED 00-00001 [data write: Broken pipe]driver: send-cmd time 11.290 to chunker0: FAILED 00-00001driver: state time 11.290 free kps: 967 space: 10478432 taper: idle idle-dumpers: 3 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 0 driver-idle: no-dumpersdriver: interface-state time 11.290 if : free -433 if ETH0: free 400 if LOCAL: free 1000driver: hdisk-state time 11.290 hdisk 0: free 10478432 dumpers 1driver: result time 11.290 from chunker0: FAILED 00-00001 [dumper returned FAILED]driver: started chunker0 pid 3130driver: send-cmd time 26.289 to chunker0: PORT-WRITE 00-00002 /var/tmp/20060329161259/manuel._boot.0 manuel fffffeff9ffeffff07 /boot 0 1970:1:1:0:0:0 1048576 GNUTAR 7328 |;auth=BSD;compress-fast;encrypt-serv-cust=/usr/local/sbin/amcrypt;server-decrypt-option=-d;chunker: pid 3130 executable chunker0 version 2.5.0chunker: try_socksize: receive buffer size is 65536chunker: bind_portrange2: trying port=687chunker: stream_server: waiting for connection: 0.0.0.0.32775driver: result time 26.297 from chunker0: PORT 32775driver: send-cmd time 26.297 to dumper0: PORT-DUMP 00-00002 32775 manuel fffffeff9ffeffff07 /boot NODEVICE 0 1970:1:1:0:0:0 GNUTAR |;auth=BSD;compress-fast;encrypt-serv-cust=/usr/local/sbin/amcrypt;server-decrypt-option=-d;dumper: time 15.197: stream_client: connected to 127.0.0.1.32775
dumper: stream_client: our side is 0.0.0.0.32776dumper: try_socksize: send buffer size is 65536chunker: stream_accept: connection from 127.0.0.1.32776chunker: try_socksize: receive buffer size is 32768dumper: time 15.216: stream_client: connected to 192.168.1.56.46456dumper: stream_client: our side is 0.0.0.0.32777dumper: try_socksize: send buffer size is 65536dumper: try_socksize: receive buffer size is 65536dumper: time 15.217: stream_client: connected to 192.168.1.56.58214dumper: stream_client: our side is 0.0.0.0.32778dumper: try_socksize: send buffer size is 65536dumper: try_socksize: receive buffer size is 65536driver: state time 26.386 free kps: 967 space: 10478432 taper: idle idle-dumpers: 3 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 0 driver-idle: no-dumpersdriver: interface-state time 26.386 if : free -433 if ETH0: free 400 if LOCAL: free 1000driver: hdisk-state time 26.386 hdisk 0: free 10478432 dumpers 1driver: result time 26.386 from dumper0: FAILED 00-00002 [data write: Broken pipe]driver: send-cmd time 26.386 to chunker0: FAILED 00-00002dumper: kill encrypt commanddriver: state time 26.387 free kps: 967 space: 10478432 taper: idle idle-dumpers: 3 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 0 driver-idle: no-dumpersdriver: interface-state time 26.387 if : free -433 if ETH0: free 400 if LOCAL: free 1000driver: hdisk-state time 26.387 hdisk 0: free 10478432 dumpers 1driver: result time 26.387 from chunker0: FAILED 00-00002 [dumper returned FAILED]driver: state time 26.389 free kps: 2000 space: 10485760 taper: idle idle-dumpers: 4 qlen tapeq: 0 runq: 0 roomq: 0 wakeup: 0 driver-idle: no-dumpersdriver: interface-state time 26.389 if : free 600 if ETH0: free 400 if LOCAL: free 1000driver: hdisk-state time 26.389 hdisk 0: free 10485760 dumpers 0driver: QUITTING time 26.389 telling children to quitdriver: send-cmd time 26.389 to dumper0: QUITdriver: send-cmd time 26.389 to dumper1: QUITdriver: send-cmd time 26.389 to dumper2: QUITdriver: send-cmd time 26.389 to dumper3: QUITdriver: send-cmd time 26.389 to taper: QUITtaper: DONE [idle wait: 15.506 secs]taper: writing end marker. [unsensitive01 OK kb 0 fm 0]driver: FINISHED time 32.693amdump: end at Wed Mar 29 16:13:32 EST 2006Scanning /var/tmp... rc_host_0: skipping cruft file, perhaps you should delete it.

Here is the log:

DISK planner manuel /boot
START planner date 20060329
INFO planner Adding new disk manuel:/boot.
START driver date 20060329
STATS driver startup time 0.020
FINISH planner date 20060329 time 0.035
START taper datestamp 20060329 label unsensitive01 tape 0
FAIL chunker manuel /boot 20060329 0 [dumper returned FAILED]
FAIL dumper manuel /boot 20060329 0 [data write: Broken pipe]
sendbackup: start [manuel:/boot level 0]
sendbackup: info BACKUP=/bin/tar
sendbackup: info RECOVER_CMD=/bin/gzip -dc |/bin/tar -f... -
sendbackup: info COMPRESS_SUFFIX=.gz
sendbackup: info end
FAIL chunker manuel /boot 20060329 0 [dumper returned FAILED]
FAIL dumper manuel /boot 20060329 0 [data write: Broken pipe]
sendbackup: start [manuel:/boot level 0]
sendbackup: info BACKUP=/bin/tar
sendbackup: info RECOVER_CMD=/bin/gzip -dc |/bin/tar -f... -
sendbackup: info COMPRESS_SUFFIX=.gz
sendbackup: info end
INFO taper tape unsensitive01 kb 0 fm 0 [OK]
FINISH driver date 20060329 time 32.693

It worked earlier today and sent me this report:

These dumps were to tape unsensitive01.
The next tape Amanda expects to use is: a new tape.


STATISTICS:
Total Full Incr.
-------- -------- --------
Estimate Time (hrs:min) 0:00
Run Time (hrs:min) 0:00
Dump Time (hrs:min) 0:00 0:00 0:00
Output Size (meg) 14.1 14.1 0.0
Original Size (meg) 14.1 14.1 0.0
Avg Compressed Size (%) -- -- --
Filesystems Dumped 1 1 0
Avg Dump Rate (k/s) 6072.6 6072.6 --

Tape Time (hrs:min) 0:00 0:00 0:00
Tape Size (meg) 14.2 14.2 0.0
Tape Used (%) 0.0 0.0 0.0
Filesystems Taped 1 1 0

Chunks Taped 0 0 0
Avg Tp Write Rate (k/s) 2085.6 2085.6 --

USAGE BY TAPE:
Label Time Size % Nb Nc
unsensitive01 0:00 14528k 0.0 1 0


NOTES:
planner: Adding new disk manuel:/boot.
taper: tape unsensitive01 kb 14528 fm 1 [OK]


DUMP SUMMARY:
DUMPER STATS TAPER STATS
HOSTNAME DISK L ORIG-kB OUT-kB COMP% MMM:SS KB/s MMM:SS KB/s
-------------------------- ------------------------------------- -------------
manuel /boot 0 14470 14528 -- 0:02 6070.8 0:07 2085.4

(brought to you by Amanda version 2.5.0)


Nothing has changed at all today, I tried new tapes/rebooting and I am getting these errors.

I have followed this guide in setting up Amanda. It makes non encrypted backups fine but encrypted backups it has issues.

http://wiki.zmanda.com/index.php/Encryption

What other information can I share with you to help solve this problem.


Thanks for all the suggestions and hints.

-Chris Vaughan

[ktill]

Hi,

I don't see anything obviously wrong in the log. My only speculaton is that amanda timed out due to encryption is taking longer than normal. What is the dtimeout value?

Send me an email (ktill at zmanda.com), I have a program for you to try out.

Thanks!

Kevin Till
Zmanda

[ktill]

I just noticed that the report summary is not right:

DUMP SUMMARY:
DUMPER STATS TAPER STATS
HOSTNAME DISK L ORIG-kB OUT-kB COMP% MMM:SS KB/s MMM:SS KB/s
-------------------------- ------------------------------------- -------------
manuel /boot 0 14470 14528 -- 0:02 6070.8 0:07 2085.4

If it's using "compress client fast", COMP% should not be ---. So your dump done this morning was not done properly for some reason.

[c-vaughan]

I removed that line as an option, our tape drive has compression so it's pointless to enable it in software.

[c-vaughan]

I finally got it running, I had some issues with path names that I resolved. I had a copy of amcrypt at this location /usr/local/sbin/amcrypt and one at this location and they were being referenced wrong /usr/sbin/amcrypt.

Thanks for the help, I appreciate it. I'll stop cursing the words that include Amanda now. ;)

[rmcgraw]

I am trying to get aespipe to work with amanda.

I downloaded the program and compiled with no errors.

I ran the test scripts and I got this error.

Error: gpg key file decryption failed

I installed the programs and ran the

head -c 2925 /dev/random | uuencode -m - | head -n 66 | tail -n 65 \
| gpg --symmetric -a >mykey1.gpg

Which ran with out problems.

I then ran

cat file | aespipe -w 10 -K mykey1.gpg

but still get the same error

Error: gpg key file decryption failed



zorn->[48] > which uuencode
/bin/uuencode
zorn->[49] > which gpg
/opt/csw/bin/gpg
zorn->[50] > which aespipe
/usr/local/bin/aespipe

Any ideas why I am getting this error? What can I do to debug this error?

Thanks

Robert

[ktill]

Try:

cat file | aespipe -w 10 -K mykey1.gpg > file.aes


It will likely prompt for a password which you provided when creating mykey1.gpg.

--Kevin Till
Zmanda

[rmcgraw]

Try:

cat file | aespipe -w 10 -K mykey1.gpg > file.aes


It will likely prompt for a password which you provided when creating mykey1.gpg.

--Kevin Till
Zmanda

This is where I have the problem. This is what I ran. I use the same password that I used to create mykey1.gpg.

##R##-zorn->[89] ##> cat ckssn.pl | aespipe -w 10 -K ./mykey1.gpg > xout
Password:
Error: gpg key file decryption failed

It has to do with when aespipe calls gpg to decrypt the mykey1.gpg file but I cannot get any output from the gpg call to see what is happening.


Also when I run "make tests' from aespipe I get
./aespipe -p 3 -e AES128 -H sha256 -C 0 -K gpgkey1.asc -G test-dir1 <test-file3 >test-file1 3<test-file4
Error: gpg key file decryption failed





Thanks

Robert

[ktill]

your gpg is installed in a very special location.

aespipe will look for gpg in the following directories: /bin, /usr/bin and /usr/local/bin.

Either install gpg to one of those directories or make a symbolic link.

--Kevin Till
Zmanda