amrecover: Error locking '/etc/amanda/monetra/changer'

[robmckennon]

Hello, I'm running amanda-server as well as amanda-client 3.3.3 on CentOS 7 and backups seem to be working fine.
Now I'm testing the recovery side of things and running into this problem when trying an amrecover as root from the client:

[[email protected] recovered]# amrecover
AMRECOVER Version 3.3.3. Contacting server on amanda-server ...
220 amanda-server AMANDA index server (3.3.3) ready.
Setting restore date to today (2015-05-18)
200 Working date set to 2015-05-18.
200 Config set to monetra.
200 Dump host set to amanda-client.
Use the setdisk command to choose dump disk to recover
amrecover> setdisk /etc
200 Disk set to /etc.
amrecover> ls
2015-05-18-12-44-16 yum/
... truncated
amrecover> add hosts
Added file /hosts
amrecover> extract

Extracting files using tape drive changer on host amanda-server.
The following tapes are needed: Tape-01

Extracting files using tape drive changer on host amanda-server.
Load tape Tape-01 now
Continue [?/Y/n/s/d]? y
Error locking '/etc/amanda/monetra/changer'
Got no header and data from server, check in amidxtaped.*.debug and amandad.*.debug files on server
amrecover> quit


----------------------------------------------------------
The amidxtaped.debug file is here:
-bash-4.2$ more amidxtaped.20150518125958.debug
Mon May 18 12:59:58 2015: thd-0x1e26600: amidxtaped: pid 23757 ruid 33 euid 33 version 3.3.3: start at Mon May 18 12:59:58 2015
Mon May 18 12:59:58 2015: thd-0x1e26600: amidxtaped: CTL << FEATURES=ffffffff9efefbffffffffff1f
Mon May 18 12:59:58 2015: thd-0x1e26600: amidxtaped: CTL << CONFIG=monetra
Mon May 18 12:59:58 2015: thd-0x1e26600: amidxtaped: CTL << LABEL=Tape-01:2
Mon May 18 12:59:58 2015: thd-0x1e26600: amidxtaped: CTL << FSF=2
Mon May 18 12:59:58 2015: thd-0x1e26600: amidxtaped: CTL << HEADER
Mon May 18 12:59:58 2015: thd-0x1e26600: amidxtaped: CTL << DEVICE=changer
Mon May 18 12:59:58 2015: thd-0x1e26600: amidxtaped: CTL << HOST=^amanda-client$
Mon May 18 12:59:58 2015: thd-0x1e26600: amidxtaped: CTL << DISK=^/etc$
Mon May 18 12:59:58 2015: thd-0x1e26600: amidxtaped: CTL << DATESTAMP=20150518124416
Mon May 18 12:59:58 2015: thd-0x1e26600: amidxtaped: CTL << END
Mon May 18 12:59:58 2015: thd-0x1e26600: amidxtaped: pid 23757 ruid 33 euid 33 version 3.3.3: rename at Mon May 18 12:59:58 2015
Mon May 18 12:59:58 2015: thd-0x1e26600: amidxtaped: new Amanda::Changer::Error: type='fatal', message='Error locking '/etc/amanda/monetra/change
r''
Mon May 18 12:59:58 2015: thd-0x1e26600: amidxtaped: Amanda::Recovery::Clerk: loading volume 'Tape-01'
Mon May 18 12:59:58 2015: thd-0x1e26600: amidxtaped: find_volume labeled 'Tape-01'
Mon May 18 12:59:58 2015: thd-0x1e26600: amidxtaped: ignoring spurious Amanda::Recovery::Scan abort call
Mon May 18 12:59:58 2015: thd-0x1e26600: amidxtaped: CTL >> MESSAGE Error locking '/etc/amanda/monetra/changer'
Mon May 18 12:59:58 2015: thd-0x1e26600: amidxtaped: exiting with 0
Mon May 18 12:59:58 2015: thd-0x1e26600: amidxtaped: pid 23757 finish time Mon May 18 12:59:58 2015

--------------------------------------------------------------------------
The amindexd file is even less useful, but here it is:
-bash-4.2$ more amindexd.20150518125816.debug
Mon May 18 12:58:16 2015: thd-0x7f38d6b8f200: amindexd: pid 23752 ruid 33 euid 33 version 3.3.3: start at Mon May 18 12:58:16 2015
Mon May 18 12:58:16 2015: thd-0x7f38d6b8f200: amindexd: version 3.3.3
Mon May 18 12:58:16 2015: thd-0x7f38d6b8f200: amindexd: < 220 amanda-server AMANDA index server (3.3.3) ready.
Mon May 18 12:58:16 2015: thd-0x7f38d6b8f200: amindexd: > FEATURES ffffffff9efefbffffffffff1f
Mon May 18 12:58:16 2015: thd-0x7f38d6b8f200: amindexd: < 200 FEATURES ffffffff9efefbffffffffff1f
Mon May 18 12:58:16 2015: thd-0x7f38d6b8f200: amindexd: > DATE 2015-05-18
Mon May 18 12:58:16 2015: thd-0x7f38d6b8f200: amindexd: < 200 Working date set to 2015-05-18.
Mon May 18 12:58:16 2015: thd-0x7f38d6b8f200: amindexd: > SCNF monetra
Mon May 18 12:58:16 2015: thd-0x7f38d6b8f200: amindexd: pid 23752 ruid 33 euid 33 version 3.3.3: rename at Mon May 18 12:58:16 2015
Mon May 18 12:58:16 2015: thd-0x7f38d6b8f200: amindexd: < 200 Config set to monetra.
Mon May 18 12:58:16 2015: thd-0x7f38d6b8f200: amindexd: > HOST amanda-client
Mon May 18 12:58:16 2015: thd-0x7f38d6b8f200: amindexd: < 200 Dump host set to amanda-client.
Mon May 18 12:58:32 2015: thd-0x7f38d6b8f200: amindexd: > DISK /etc
Mon May 18 12:58:32 2015: thd-0x7f38d6b8f200: amindexd: no recovery limit found; allowing access
Mon May 18 12:58:32 2015: thd-0x7f38d6b8f200: amindexd: append_to_tapelist(tapelist=(nil), label='Tape-01', file=2, partnum=1, isafile=0)
Mon May 18 12:58:32 2015: thd-0x7f38d6b8f200: amindexd: - 2015-05-18-12-44-16 0 Tape-01 2 1 1
Mon May 18 12:58:32 2015: thd-0x7f38d6b8f200: amindexd: < 200 Disk set to /etc.
Mon May 18 12:58:32 2015: thd-0x7f38d6b8f200: amindexd: > OISD /
Mon May 18 12:58:32 2015: thd-0x7f38d6b8f200: amindexd: Spawning "/usr/bin/gzip /usr/bin/gzip -dc /etc/amanda/state/index/amanda-client/_etc/2015
0518124416_0.gz" in pipeline
Mon May 18 12:58:32 2015: thd-0x7f38d6b8f200: amindexd: Spawning "/usr/bin/sort /usr/bin/sort" in pipeline
Mon May 18 12:58:32 2015: thd-0x7f38d6b8f200: amindexd: f /etc/amanda/state/index/amanda-client/_etc/20150518124416_0
Mon May 18 12:58:32 2015: thd-0x7f38d6b8f200: amindexd: < 200 "/" is a valid directory
Mon May 18 12:58:32 2015: thd-0x7f38d6b8f200: amindexd: > OLSD /
Mon May 18 12:58:32 2015: thd-0x7f38d6b8f200: amindexd: < 200- Opaque list of /
Mon May 18 12:58:32 2015: thd-0x7f38d6b8f200: amindexd: < 200 Opaque list of /
Mon May 18 12:58:32 2015: thd-0x7f38d6b8f200: amindexd: > DLE
Mon May 18 12:58:32 2015: thd-0x7f38d6b8f200: 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</dle>\n"
Mon May 18 12:59:57 2015: thd-0x7f38d6b8f200: amindexd: > TAPE
Mon May 18 12:59:57 2015: thd-0x7f38d6b8f200: amindexd: tapedev_is amrecover_changer: changer
Mon May 18 12:59:57 2015: thd-0x7f38d6b8f200: amindexd: < 200 changer
Mon May 18 13:00:22 2015: thd-0x7f38d6b8f200: amindexd: > QUIT
Mon May 18 13:00:22 2015: thd-0x7f38d6b8f200: amindexd: removing index file: /etc/amanda/state/index/amanda-client/_etc/20150518124416_0
Mon May 18 13:00:22 2015: thd-0x7f38d6b8f200: amindexd: < 200 Good bye.
Mon May 18 13:00:22 2015: thd-0x7f38d6b8f200: amindexd: pid 23752 finish time Mon May 18 13:00:22 2015


----------------------------------------------------------------------------------
And just for fun, here is the amandad.debug file:
-bash-4.2$ more amandad.20150518125816.debug
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: pid 23751 ruid 33 euid 33 version 3.3.3: start at Mon May 18 12:58:16 2015
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: security_getdriver(name=bsdtcp) returns 0x7f8c7d3167e0
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: version 3.3.3
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: build: VERSION="Amanda-3.3.3"
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: BUILT_DATE="Tue Jun 10 01:33:40 UTC 2014" BUILT_MACH=""
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: BUILT_REV="5099" BUILT_BRANCH="community_3_3_3" CC="gcc"
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: paths: bindir="/usr/bin" sbindir="/usr/sbin"
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: libexecdir="/usr/lib64" amlibexecdir="/usr/lib64/amanda"
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: mandir="/usr/share/man" AMANDA_TMPDIR="/var/log/amanda"
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: AMANDA_DBGDIR="/var/log/amanda" CONFIG_DIR="/etc/amanda"
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: DEV_PREFIX="/dev/" RDEV_PREFIX="/dev/" DUMP=UNDEF
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: RESTORE=UNDEF VDUMP=UNDEF VRESTORE=UNDEF XFSDUMP=UNDEF
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: XFSRESTORE=UNDEF VXDUMP=UNDEF VXRESTORE=UNDEF
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: SAMBA_CLIENT="/usr/bin/smbclient" GNUTAR="/bin/tar"
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: COMPRESS_PATH="/usr/bin/gzip"
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: UNCOMPRESS_PATH="/usr/bin/gzip" LPRCMD=UNDEF MAILER=UNDEF
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: listed_incr_dir="/var/lib/amanda/gnutar-lists"
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: defs: DEFAULT_SERVER="amandahost" DEFAULT_CONFIG="DailySet1"
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: DEFAULT_TAPE_SERVER="amandahost" DEFAULT_TAPE_DEVICE=""
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: NEED_STRSTR AMFLOCK_POSIX AMFLOCK_FLOCK AMFLOCK_LOCKF
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: AMFLOCK_LNLOCK SETPGRP_VOID AMANDA_DEBUG_DAYS=4 BSD_SECURITY
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: KRB5_SECURITY RSH_SECURITY USE_AMANDAHOSTS
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: CLIENT_LOGIN="amandabackup" CHECK_USERID HAVE_GZIP
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: COMPRESS_SUFFIX=".gz" COMPRESS_FAST_OPT="--fast"
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: COMPRESS_BEST_OPT="--best" UNCOMPRESS_OPT="-dc"
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: security_handleinit(handle=0x7f8c7dad76d0, driver=0x7f8c7d3167e0 (BSDTCP))
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: security_streaminit(stream=0x7f8c7dad77e0, driver=0x7f8c7d3167e0 (BSDTCP))
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: authenticated peer name is 'amanda-client'
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: accept recv REQ pkt:
<<<<<
SERVICE amindexd
OPTIONS features=ffffffff9efefbffffffffff1f;auth=bsdtcp;
>>>>>
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: creating new service: amindexd
OPTIONS features=ffffffff9efefbffffffffff1f;auth=bsdtcp;

Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: sending ACK pkt:
<<<<<
>>>>>
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: tcpm_send_token: data is still flowing
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: security_streaminit(stream=0x7f8c7daf05d0, driver=0x7f8c7d3167e0 (BSDTCP))
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: sending REP pkt:
<<<<<
CONNECT MESG 499999

>>>>>
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: received ACK pkt:
<<<<<
>>>>>
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: opening security stream for fd 50
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: security_close(handle=0x7f8c7dad76d0, driver=0x7f8c7d3167e0 (BSDTCP))
Mon May 18 12:58:16 2015: thd-0x7f8c7dacd200: amandad: security_stream_close(0x7f8c7dad77e0)
Mon May 18 12:58:32 2015: thd-0x7f8c7dacd200: amandad: stream_read_callback: data is still flowing
Mon May 18 12:59:57 2015: thd-0x7f8c7dacd200: amandad: stream_read_callback: data is still flowing
Mon May 18 12:59:58 2015: thd-0x7f8c7dacd200: amandad: security_handleinit(handle=0x7f8c7dad76d0, driver=0x7f8c7d3167e0 (BSDTCP))
Mon May 18 12:59:58 2015: thd-0x7f8c7dacd200: amandad: security_streaminit(stream=0x7f8c7dad77e0, driver=0x7f8c7d3167e0 (BSDTCP))
Mon May 18 12:59:58 2015: thd-0x7f8c7dacd200: amandad: authenticated peer name is 'amanda-client'
Mon May 18 12:59:58 2015: thd-0x7f8c7dacd200: amandad: accept recv REQ pkt:
<<<<<
SERVICE amidxtaped
OPTIONS features=ffffffff9efefbffffffffff1f;auth=bsdtcp;
>>>>>
Mon May 18 12:59:58 2015: thd-0x7f8c7dacd200: amandad: creating new service: amidxtaped
OPTIONS features=ffffffff9efefbffffffffff1f;auth=bsdtcp;

Mon May 18 12:59:58 2015: thd-0x7f8c7dacd200: amandad: sending ACK pkt:
<<<<<
>>>>>
Mon May 18 12:59:58 2015: thd-0x7f8c7dacd200: amandad: security_streaminit(stream=0x7f8c7db08b70, driver=0x7f8c7d3167e0 (BSDTCP))
Mon May 18 12:59:58 2015: thd-0x7f8c7dacd200: amandad: security_streaminit(stream=0x7f8c7db10bd0, driver=0x7f8c7d3167e0 (BSDTCP))
Mon May 18 12:59:58 2015: thd-0x7f8c7dacd200: amandad: sending REP pkt:
<<<<<
CONNECT CTL 499998 DATA 499997

>>>>>
Mon May 18 12:59:58 2015: thd-0x7f8c7dacd200: amandad: received ACK pkt:
<<<<<
>>>>>
Mon May 18 12:59:58 2015: thd-0x7f8c7dacd200: amandad: opening security stream for fd 50
Mon May 18 12:59:58 2015: thd-0x7f8c7dacd200: amandad: opening security stream for fd 51
Mon May 18 12:59:58 2015: thd-0x7f8c7dacd200: amandad: security_close(handle=0x7f8c7dad76d0, driver=0x7f8c7d3167e0 (BSDTCP))
Mon May 18 12:59:58 2015: thd-0x7f8c7dacd200: amandad: security_stream_close(0x7f8c7dad77e0)
Mon May 18 12:59:58 2015: thd-0x7f8c7dacd200: amandad: security_stream_close(0x7f8c7db10bd0)
Mon May 18 12:59:58 2015: thd-0x7f8c7dacd200: amandad: security_stream_close(0x7f8c7db08b70)
Mon May 18 13:00:22 2015: thd-0x7f8c7dacd200: amandad: stream_read_callback: data is still flowing
Mon May 18 13:00:22 2015: thd-0x7f8c7dacd200: amandad: security_stream_close(0x7f8c7daf05d0)
Mon May 18 13:00:22 2015: thd-0x7f8c7dacd200: amandad: pid 23751 finish time Mon May 18 13:00:22 2015



I have looked through the forums and can't find any solutions to this specific problem. Any suggestions on how to proceed getting a recover to work?

Rob McKennon
Unix Admin

[robmckennon]

Nevermind, after disabling SE-Linux (setenforce 0) it's working. Now to figure out exactly how to fix it properly!

Hopefully this will help someone!

Rob.

[robmckennon]

So, Here's my fix for the se-linux workaround:

yum -y install policycoreutils-python
semanage fcontext -a -t amanda_data_t "/etc/amanda/DailySet1(/.*)?"
restorecon -R -v /etc/amanda/

# Then I ran into problems with it trying to write to the backup directory:
# type=AVC msg=audit(1432070862.516:78034): avc: denied { create } for pid=3610 comm="amidxtaped" name="data"
scontext=system_u:system_r:amanda_t:s0 tcontext=system_ubject_r:amanda_var_lib_t:s0 tclass=lnk_file
type=SYSCALL msg=audit(1432070862.516:78034): arch=c000003e syscall=88 success=no exit=-13 a0=1759f80 a1=175b7
40 a2=16fbe80 a3=1 items=0 ppid=3601 pid=3610 auid=4294967295 uid=33 gid=6 euid=33 suid=33 fsuid=33 egid=6 sgi
d=6 fsgid=6 tty=(none) ses=4294967295 comm="amidxtaped" exe="/usr/bin/perl" subj=system_u:system_r:amanda_t:s0
key=(null)

# So I added this:
# /var/lib/amanda/backup is where my external drive is mounted.

semanage fcontext -a -t amanda_data_t '/var/lib/amanda/backup(/.*)?'
restorecon -Rv /var/lib/amanda/backup

And now all is well in Amanda-Land.

Well, at least so far...

Rob.

p.s. I don't know if this is the most correct way to fix it or not, but it does work.