I recently did a do-release-upgrade on one of my Amanda servers, taking it from Ubuntu 14.04 Server
LTS to Ubuntu 16.04 Server LTS. With the update of all the libraries, etc., I had to recompile
Amanda. So, I took the opportunity to upgrade Amanda from 3.3.6 to 3.5.1 (`make uninstall` the one
before starting with the next). It went relatively smoothly (used`sudo ./configure
--with-user=amanda --with-group=amanda --without-ipv6 --with-ssh-security`), with a few glitches
that I'm used to that had to be fixed after the install. Had to fix permissions at and beneath
/usr/local/share/perl/5.22.1/, install the libjson-perl package, etc.
However, I'm stuck on this one. It was last Thursday that I did the upgrade. Backups ran Thursday
evening, and all the other servers it was backing up were successfully backed up, but localhost was
not. I checked some of the usual culprits such as the location and permissions of
amanda-security.conf, etc.
Now, I'm getting most of the DLEs for localhost backed up, but three are repeatedly failing. The
Amanda email report starts with
localhost /data lev 0 FAILED [data timeout]
localhost /data lev 0 FAILED [Got empty header]
It turns out that the three failing DLEs are all on "/", that is, they don't have separate mount
points and/or partitions. There are several other DLEs whose full path is in /data, but they are
separate volumes with mount points in /data, and they get backed up. I checked the kern.log thinking
maybe there was a problem with the disk that is "/", but the kern.log has almost nothing in it and
no mention of any problems anywhere. Also, /etc is backed up successfully, and it is on that same
"/", which is a mirrored root drive.
amcheck claims no problems:
amanda@wahoo:~$ amcheck daily
Amanda Tape Server Host Check
-----------------------------
NOTE: Holding disk '/amanda1': 437825536 KB disk space available, using
427339776 KB
NOTE: Holding disk '/amanda2': 437825536 KB disk space available, using
427339776 KB
slot 6: volume 'ISB-Daily-006'
Will write to volume 'ISB-Daily-006' in slot 6.
NOTE: skipping tape-writable test
Server check took 0.594 seconds
Amanda Backup Client Hosts Check
--------------------------------
Client check: 4 hosts checked in 3.059 seconds. 0 problems found.
(brought to you by Amanda 3.5.1)
amanda@wahoo:~$
tar is a locally built 1.29 at /usr/local/bin/tar. The version that came in with Ubuntu 16.04 is
/bin/tar and is 1.28. The backup is using local-comp-user-tar. Should I try switching everything to
amgtar? I'm using that on at least one other server that has much much larger and more complex drive
assemblies and LVMs.
I've copied some of the debug log files below.
--
---------------
Chris Hoogendyk
-
O__ ---- Systems Administrator
c/ /'_ --- Biology & Geosciences Departments
(*) \(*) -- 315 Morrill Science Center
~~~~~~~~~~ - University of Massachusetts, Amherst
<hoogen...@bio.umass.edu>
---------------
Erdös 4
--------------- Section of
/tmp/amanda/server/daily/dumper.20190114224002000.debug -----------------
SERVICE sendbackup
OPTIONS
features=ffffffff9efefbfffffffffffffff3fffbf71f;maxdumps=1;hostname=localhost;config=daily;timestamp=20190114224001;data-shm-control-name=/amanda_shm_control-30920-0;
<dle>
<program>GNUTAR</program>
<disk>/data</disk>
<level>0</level>
<auth>local</auth>
<compress>FAST</compress>
<record>YES</record>
<index>YES</index>
<datapath>AMANDA</datapath>
</dle>
----
Mon Jan 14 22:52:08.876122021 2019: pid 30449: thd-0x839e00: dumper:
security_getdriver(name=local) returns 0x7fc5bdd60a00
Mon Jan 14 22:52:08.877094986 2019: pid 30923: thd-0x839e00: dumper: Executing:
/usr/bin/lsb_release '--id' '-s'
Mon Jan 14 22:52:08.939296138 2019: pid 30924: thd-0x839e00: dumper: Executing:
/usr/bin/lsb_release '--description' '-s'
Mon Jan 14 22:52:08.997940727 2019: pid 30449: thd-0x86ed40: dumper:
security_handleinit(handle=0x7fc5b40246a0, driver=0x7fc5bdd60a00 (LOCAL))
Mon Jan 14 22:52:08.998212439 2019: pid 30449: thd-0x86ed40: dumper:
security_streaminit(stream=0x7fc5b4056e30, driver=0x7fc5bdd60a00 (LOCAL))
Mon Jan 14 22:52:09.998095734 2019: pid 30449: thd-0x839e00: dumper:
tcpm_send_token: data is still flowing
Mon Jan 14 22:52:10.008113852 2019: pid 30449: thd-0x839e00: dumper: got
response:
----
CONNECT DATA 499999 MESG 499998 INDEX 499997 STATE 499996
OPTIONS features=ffffffff9efefbfffffffffffffff3fffbf71f;
----
Mon Jan 14 22:52:10.008207510 2019: pid 30449: thd-0x839e00: dumper:
security_streaminit(stream=0x9729c0, driver=0x7fc5bdd60a00 (LOCAL))
Mon Jan 14 22:52:10.008260895 2019: pid 30449: thd-0x839e00: dumper:
security_streaminit(stream=0x97aa60, driver=0x7fc5bdd60a00 (LOCAL))
Mon Jan 14 22:52:10.008340144 2019: pid 30449: thd-0x839e00: dumper:
security_streaminit(stream=0x982b00, driver=0x7fc5bdd60a00 (LOCAL))
Mon Jan 14 22:52:10.008414203 2019: pid 30449: thd-0x839e00: dumper:
security_streaminit(stream=0x98aba0, driver=0x7fc5bdd60a00 (LOCAL))
Mon Jan 14 22:52:10.008437799 2019: pid 30449: thd-0x839e00: dumper:
security_close(handle=0x7fc5b40246a0, driver=0x7fc5bdd60a00 (LOCAL))
Mon Jan 14 22:52:10.008455449 2019: pid 30449: thd-0x839e00: dumper:
security_stream_close(0x7fc5b4056e30)
Mon Jan 14 22:52:10.008696942 2019: pid 30449: thd-0x839e00: dumper: execute:
/bin/gzip --best
Mon Jan 14 22:52:10.009551657 2019: pid 30449: thd-0x839e00: dumper: ignoring
close stream 9
Mon Jan 14 22:52:10.009650632 2019: pid 30449: thd-0x839e00: dumper:
security_stream_seterr(0x98aba0, EOF)
Mon Jan 14 22:52:10.009670643 2019: pid 30449: thd-0x839e00: dumper:
security_stream_close(0x98aba0)
Mon Jan 14 23:52:11.046947088 2019: pid 30449: thd-0x839e00: dumper:
security_stream_close(0x9729c0)
Mon Jan 14 23:52:11.046994148 2019: pid 30449: thd-0x839e00: dumper:
tcpm_send_token: data is still flowing
Mon Jan 14 23:52:11.047023912 2019: pid 30449: thd-0x839e00: dumper:
security_stream_close(0x97aa60)
Mon Jan 14 23:52:11.047044293 2019: pid 30449: thd-0x839e00: dumper:
security_stream_close(0x982b00)
Mon Jan 14 23:52:11.047067174 2019: pid 30449: thd-0x839e00: dumper: stop_dump:
cancelling shm-ring-direct
Mon Jan 14 23:52:11.047850449 2019: pid 30449: thd-0x839e00: dumper: putresult: 10 FAILED
01-00035 "[data timeout]"
Mon Jan 14 23:52:11.048226416 2019: pid 30449: thd-0x839e00: dumper:
close_producer_shm_ring sem_close(sem_write 0x7fc5be01c000
Mon Jan 14 23:52:11.048249602 2019: pid 30449: thd-0x839e00: dumper:
am_sem_close 0x7fc5be01c000 0
Mon Jan 14 23:52:11.048290123 2019: pid 30449: thd-0x839e00: dumper:
am_sem_close 0x7fc5be00c000 0
Mon Jan 14 23:52:11.048350970 2019: pid 30449: thd-0x839e00: dumper:
am_sem_close 0x7fc5be014000 0
Mon Jan 14 23:52:11.048379828 2019: pid 30449: thd-0x839e00: dumper:
am_sem_close 0x7fc5be004000 0
Mon Jan 14 23:52:11.311354084 2019: pid 30449: thd-0x839e00: dumper: getcmd: SHM-DUMP 01-00099 48051 NULL 1 localhost ffffffff9efefbfffffffffffffff3fffbf71f /data NODEVICE 0 1970:1:1:0:0:0 GNUTAR "" "" ""
"" "" "" "" 1 "" /usr/local/etc/amanda/.ssh/id_rsa_daily_config local AMANDA /amanda_shm_control-31669-0 20 |" <auth>local</auth>\n
<compress>FAST</compress>\n <record>YES</record>\n <index>YES</index>\n <datapath>AMANDA</datapath>\n"""
Mon Jan 14 23:52:11.311500567 2019: pid 30449: thd-0x839e00: dumper: Sending
header to localhost:48051
Mon Jan 14 23:52:11.311912953 2019: pid 30449: thd-0x839e00: dumper:
make_socket opening socket with family 2
Mon Jan 14 23:52:11.311934862 2019: pid 30449: thd-0x839e00: dumper:
make_socket opening socket with family 2: 3
Mon Jan 14 23:52:11.311954135 2019: pid 30449: thd-0x839e00: dumper:
connect_port: Try port 1024: available - Success
Mon Jan 14 23:52:11.312057308 2019: pid 30449: thd-0x839e00: dumper: connected
to 127.0.0.1:48051
Mon Jan 14 23:52:11.312071549 2019: pid 30449: thd-0x839e00: dumper: our side
is 0.0.0.0:1024
Mon Jan 14 23:52:11.312086959 2019: pid 30449: thd-0x839e00: dumper:
try_socksize: send buffer size is 131072
Mon Jan 14 23:52:11.312174606 2019: pid 30449: thd-0x839e00: dumper:
shm_ring_link /amanda_shm_control-31669-0
Mon Jan 14 23:52:11.312227037 2019: pid 30449: thd-0x839e00: dumper:
am_sem_open 0x7fc5be01c000 1
Mon Jan 14 23:52:11.312250624 2019: pid 30449: thd-0x839e00: dumper:
am_sem_open 0x7fc5be014000 1
Mon Jan 14 23:52:11.312272890 2019: pid 30449: thd-0x839e00: dumper:
am_sem_open 0x7fc5be00c000 1
Mon Jan 14 23:52:11.312312259 2019: pid 30449: thd-0x839e00: dumper:
am_sem_open 0x7fc5be004000 1
Mon Jan 14 23:52:11.312345268 2019: pid 30449: thd-0x839e00: dumper: send
request:
----
---------------- Contents of
/tmp/amanda/client/daily/sendbackup.20190114225210.debug ---------------------
Mon Jan 14 22:52:10.006330352 2019: pid 30927: thd-0xe81a00: sendbackup: pid
30927 ruid 555 euid 555 version 3.5.1: start at Mon Jan 14 22:52:10 2019
Mon Jan 14 22:52:10.006394421 2019: pid 30927: thd-0xe81a00: sendbackup:
Version 3.5.1
Mon Jan 14 22:52:10.006638009 2019: pid 30927: thd-0xe81a00: sendbackup:
reading config file /usr/local/etc/amanda/daily/amanda-client.conf
Mon Jan 14 22:52:10.007211842 2019: pid 30927: thd-0xe81a00: sendbackup: pid
30927 ruid 555 euid 555 version 3.5.1: rename at Mon Jan 14 22:52:10 2019
Mon Jan 14 22:52:10.007431598 2019: pid 30927: thd-0xe81a00: sendbackup:
Parsed request as: program `GNUTAR'
Mon Jan 14 22:52:10.007449218 2019: pid 30927: thd-0xe81a00: sendbackup:
disk `/data'
Mon Jan 14 22:52:10.007461892 2019: pid 30927: thd-0xe81a00: sendbackup:
device `/data'
Mon Jan 14 22:52:10.007473813 2019: pid 30927: thd-0xe81a00: sendbackup:
level 0
Mon Jan 14 22:52:10.007485476 2019: pid 30927: thd-0xe81a00: sendbackup:
since NODATE
Mon Jan 14 22:52:10.007496996 2019: pid 30927: thd-0xe81a00: sendbackup:
options `'
Mon Jan 14 22:52:10.007509353 2019: pid 30927: thd-0xe81a00: sendbackup:
datapath `AMANDA'
Mon Jan 14 22:52:10.007628248 2019: pid 30927: thd-0xe81a00: sendbackup: start:
localhost:/data lev 0
Mon Jan 14 22:52:10.007676311 2019: pid 30927: thd-0xe81a00: sendbackup: Spawning
"/bin/gzip /bin/gzip --fast" in pipeline
Mon Jan 14 22:52:10.007980333 2019: pid 30927: thd-0xe81a00: sendbackup:
gnutar: pid 30929: /bin/gzipMon Jan 14 22:52:10.008033155 2019: pid 30927:
thd-0xe81a00: sendbackup: pid 30929: /bin/gzip --fast
Mon Jan 14 22:52:10.008123564 2019: pid 30927: thd-0xe81a00: sendbackup: doing
level 0 dump as listed-incremental to
'/usr/local/var/amanda/gnutar-lists/localhost_data_0.new'
Mon Jan 14 22:52:10.010564875 2019: pid 30927: thd-0xe81a00: sendbackup: Spawning
"/usr/local/libexec/amanda/runtar runtar daily /usr/local/bin/tar --create --file -
--directory /data --one-file-system --listed-incremental
/usr/local/var/amanda/gnutar-lists/localhost_data_0.new --sparse --ignore-failed-read
--totals ." in pipeline
Mon Jan 14 22:52:10.010752999 2019: pid 30932: thd-0xe81a00: sendbackup: Dupped
file descriptor 3 to 11
Mon Jan 14 22:52:10.010898464 2019: pid 30927: thd-0xe81a00: sendbackup:
gnutar: /usr/local/libexec/amanda/runtar: pid 30933
Mon Jan 14 22:52:10.010959852 2019: pid 30927: thd-0xe81a00: sendbackup:
shm_ring_link /amanda_shm_control-30920-0
Mon Jan 14 22:52:10.011092056 2019: pid 30927: thd-0xe81a00: sendbackup:
am_sem_open 0x7ff0dcc6c000 1
Mon Jan 14 22:52:10.011122922 2019: pid 30927: thd-0xe81a00: sendbackup:
am_sem_open 0x7ff0dcc64000 1
Mon Jan 14 22:52:10.011157545 2019: pid 30927: thd-0xe81a00: sendbackup:
am_sem_open 0x7ff0dcc5c000 1
Mon Jan 14 22:52:10.011185967 2019: pid 30927: thd-0xe81a00: sendbackup:
am_sem_open 0x7ff0dcc54000 1
Mon Jan 14 22:52:10.011199828 2019: pid 30927: thd-0xe81a00: sendbackup:
shm_ring_producer_set_size
Mon Jan 14 22:52:10.011409749 2019: pid 30927: thd-0xe81a00: sendbackup:
Started backup
Mon Jan 14 22:52:10.011605676 2019: pid 30927: thd-0xe94050: sendbackup:
fd_to_shm_ring
Mon Jan 14 22:52:10.012075246 2019: pid 30932: thd-0xe81a00: sendbackup: Started index
creator: "/usr/local/bin/tar -tf - 2>/dev/null | sed -e 's/^\.//'"
Mon Jan 14 22:52:10.043334059 2019: pid 30927: thd-0xe81a00: sendbackup: 119:
strange(?): /usr/local/bin/tar: ./MBoMS: directory is on a different
filesystem; not dumped
Mon Jan 14 22:52:10.043409029 2019: pid 30927: thd-0xe81a00: sendbackup: 119:
strange(?): /usr/local/bin/tar: ./bioimaging: directory is on a different
filesystem; not dumped
Mon Jan 14 22:52:10.043443765 2019: pid 30927: thd-0xe81a00: sendbackup: 119:
strange(?): /usr/local/bin/tar: ./capstone: directory is on a different
filesystem; not dumped
Mon Jan 14 22:52:10.043475754 2019: pid 30927: thd-0xe81a00: sendbackup: 119:
strange(?): /usr/local/bin/tar: ./quantbiol: directory is on a different
filesystem; not dumped
Mon Jan 14 23:52:11.047277210 2019: pid 30927: thd-0xe81a00: sendbackup: 119:
strange(?):
Mon Jan 14 23:52:11.047365569 2019: pid 30927: thd-0xe81a00: sendbackup: 119:
strange(?): gzip: stdout: Broken pipe
Mon Jan 14 23:52:14.329611309 2019: pid 30932: thd-0xe81a00: sendbackup:
critical (fatal): index tee cannot write [Broken pipe]
/usr/local/lib/amanda/libamanda-3.5.1.so(+0x398c7)[0x7ff0dc54d8c7]
/lib/x86_64-linux-gnu/libglib-2.0.so.0(g_logv+0x1f4)[0x7ff0dc24ca44]
/lib/x86_64-linux-gnu/libglib-2.0.so.0(g_log+0x8f)[0x7ff0dc24cc6f]
/usr/local/libexec/amanda/sendbackup(start_index+0x2b8)[0x408068]
/usr/local/libexec/amanda/sendbackup[0x408f36]
/usr/local/libexec/amanda/sendbackup(main+0x12fe)[0x404e3e]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf0)[0x7ff0dbc2c830]
/usr/local/libexec/amanda/sendbackup(_start+0x29)[0x4064e9]
-----------------------------------------
