tar crashing?, chunker hanging with 3.4.5
Orion Poplawski <[email protected]> Wed, 28 Jun 2017 11:46:19 -0600
| Newsgroups | gmane.comp.archivers.amanda.devel |
|---|---|
| Message-ID | <[email protected]> |
Since updating to 3.4 (now 3.4.5) I've had a couple instances where tar seems
to have died and amanda simply hangs waiting for it.
On the client:
# pstree -p 4260 -a -l -u
amandad,4260,amandabackup -auth=bsdtcp amdump amindexd amidxtaped
├─(amandad,4262)
├─sendbackup,4261 amandad bsdtcp --shm-name /amanda_shm_control-4260-0
│ ├─amgtar,4265 backup --message line --config Data --host alxdisk1ib
--disk /export/clouds/AIRS --device /export/clouds/AIRS --level 0 --index line
--state-stream 156 --record --exclude-file ./AIRSgroup/retrieval
--exclude-file ./AIRSgroup/BT4m --exclude-list
/usr/local/lib/amanda/exclude.gtar --amfeatures
ffffffff9efefbfffffffffffffff3fffbf70f --atime-preserve no --check-device NO
│ │ ├─tar,4269,root --create --verbose --block-number --file -
--directory /export/clouds/AIRS --one-file-system --no-check-device
--listed-incremental
/var/lib/amanda/gnutar-lists/alxdisk1ib_export_clouds_AIRS_0.new
--ignore-failed-read --totals --exclude-from
/var/log/amanda/amgtar._export_clouds_AIRS.20170627213233.exclude .
│ │ └─(tar,4267)
│ └─{sendbackup},4266
└─{amandad},4264
4262 and 4267 appear to be zombies.
the 4269 tar process is stuck in write():
# strace -fp 4269
Process 4269 attached
write(1,
"\257{\227FA\263xJ\257\201SFA\263xJ\257\207\21PA\263xJ\257\214\321RA\263xJ"...,
6144
# strace -fp 4265
Process 4265 attached
read(7,
so amgtar is stuck reading from some pipe:
amgtar 4265 amandabackup 7r FIFO 0,8 0t0 3640033 pipe
nothing in the amgtar debug log:
Tue Jun 27 21:32:33.656526839 2017: pid 4268: thd-0x7fe6ecb44600: amgtar:
Executing: /usr/bin/tar '--version'
Tue Jun 27 21:32:33.658305736 2017: pid 4265: thd-0x7fe6ecb44600: amgtar:
Spawning "/usr/bin/tar /usr/bin/tar --create --verbose --block-number --file -
--directory /export/clouds/AIRS --one-file-system --no-check-device
--listed-incremental
/var/lib/amanda/gnutar-lists/alxdisk1ib_export_clouds_AIRS_0.new
--ignore-failed-read --totals --exclude-from
/var/log/amanda/amgtar._export_clouds_AIRS.20170627213233.exclude ." in pipeline
or in sendbackup - simply the amgtar arguments:
Tue Jun 27 21:32:33.644033104 2017: pid 4265: thd-0x7fb73e877400: sendbackup:
sendbackup: running "/usr/lib64/amanda/application/amgtar
Tue Jun 27 21:32:33.644087729 2017: pid 4265: thd-0x7fb73e877400: sendbackup:
backup
Tue Jun 27 21:32:33.644099207 2017: pid 4265: thd-0x7fb73e877400: sendbackup:
--message
Tue Jun 27 21:32:33.644118358 2017: pid 4265: thd-0x7fb73e877400: sendbackup:
line
Tue Jun 27 21:32:33.644119421 2017: pid 4261: thd-0x7fb73e888c00: sendbackup:
fd_to_shm_ring
Tue Jun 27 21:32:33.644129026 2017: pid 4265: thd-0x7fb73e877400: sendbackup:
--config
Tue Jun 27 21:32:33.644150875 2017: pid 4265: thd-0x7fb73e877400: sendbackup:
Data
Tue Jun 27 21:32:33.644160099 2017: pid 4265: thd-0x7fb73e877400: sendbackup:
--host
Tue Jun 27 21:32:33.644169172 2017: pid 4265: thd-0x7fb73e877400: sendbackup:
alxdisk1ib
Tue Jun 27 21:32:33.644178226 2017: pid 4265: thd-0x7fb73e877400: sendbackup:
--disk
Tue Jun 27 21:32:33.644187276 2017: pid 4265: thd-0x7fb73e877400: sendbackup:
/export/clouds/AIRS
Tue Jun 27 21:32:33.644196451 2017: pid 4265: thd-0x7fb73e877400: sendbackup:
--device
Tue Jun 27 21:32:33.644205493 2017: pid 4265: thd-0x7fb73e877400: sendbackup:
/export/clouds/AIRS
Tue Jun 27 21:32:33.644214475 2017: pid 4265: thd-0x7fb73e877400: sendbackup:
--level
Tue Jun 27 21:32:33.644223485 2017: pid 4265: thd-0x7fb73e877400: sendbackup: 0
Tue Jun 27 21:32:33.644232477 2017: pid 4265: thd-0x7fb73e877400: sendbackup:
--index
Tue Jun 27 21:32:33.644241444 2017: pid 4265: thd-0x7fb73e877400: sendbackup:
line
Tue Jun 27 21:32:33.644250477 2017: pid 4265: thd-0x7fb73e877400: sendbackup:
--state-stream
Tue Jun 27 21:32:33.644259619 2017: pid 4265: thd-0x7fb73e877400: sendbackup: 156
Tue Jun 27 21:32:33.644268606 2017: pid 4265: thd-0x7fb73e877400: sendbackup:
--record
Tue Jun 27 21:32:33.644277665 2017: pid 4265: thd-0x7fb73e877400: sendbackup:
--exclude-file
Tue Jun 27 21:32:33.644286682 2017: pid 4265: thd-0x7fb73e877400: sendbackup:
./AIRSgroup/retrieval
Tue Jun 27 21:32:33.644297565 2017: pid 4265: thd-0x7fb73e877400: sendbackup:
--exclude-file
Tue Jun 27 21:32:33.644307175 2017: pid 4265: thd-0x7fb73e877400: sendbackup:
./AIRSgroup/BT4m
Tue Jun 27 21:32:33.644316336 2017: pid 4265: thd-0x7fb73e877400: sendbackup:
--exclude-list
Tue Jun 27 21:32:33.644325444 2017: pid 4265: thd-0x7fb73e877400: sendbackup:
/usr/local/lib/amanda/exclude.gtar
Tue Jun 27 21:32:33.644335834 2017: pid 4265: thd-0x7fb73e877400: sendbackup:
--amfeatures
Tue Jun 27 21:32:33.644345673 2017: pid 4265: thd-0x7fb73e877400: sendbackup:
ffffffff9efefbfffffffffffffff3fffbf70f
Tue Jun 27 21:32:33.644356111 2017: pid 4265: thd-0x7fb73e877400: sendbackup:
--atime-preserve
Tue Jun 27 21:32:33.644365778 2017: pid 4265: thd-0x7fb73e877400: sendbackup: no
Tue Jun 27 21:32:33.644375220 2017: pid 4265: thd-0x7fb73e877400: sendbackup:
--check-device
Tue Jun 27 21:32:33.644384692 2017: pid 4265: thd-0x7fb73e877400: sendbackup: NO
Tue Jun 27 21:32:33.644394119 2017: pid 4265: thd-0x7fb73e877400: sendbackup: "
On the server amdump simply has the start of the dump:
driver: send-cmd time 1894.614 to dumper0: PORT-DUMP 00-00001 38297 NULL 2
alxdisk1ib ffffffff9efefbfffffffffffffff3fffbf70f /export/clouds/AIRS NODEVICE
0 1970:1:1:0:0:0 amgtar "" "" "" "" "" "" "" 1 "" "" BSDTCP AMANDA
127.0.0.1:54312 20 |" <auth>BSDTCP</auth>\n
<compress>SERVER-CUSTOM<custom-compress-program>/usr/local/bin/pigz-fast</custom-compress-program>\n
</compress>\n <record>YES</record>\n <index>YES</index>\n
<datapath>AMANDA</datapath>\n <exclude>\n
<file>./AIRSgroup/retrieval</file>\n <file>./AIRSgroup/BT4m</file>\n
<list>/usr/local/lib/amanda/exclude.gtar</list>\n </exclude>\n""""
<backup-program>\n <plugin>amgtar</plugin>\n <property>\n
<name>atime-preserve</name>\n <value>no</value>\n </property>\n
<property>\n <name>check-device</name>\n <value>NO</value>\n
</property>\n </backup-program>\n"
dumper log ends with:
Tue Jun 27 23:14:07.002241659 2017: pid 10786: thd-0x2b22629e5400: dumper:
stream_read_callback: data is still flowing
It's stuck in write:
# strace -fp 10786
Process 10786 attached
write(4,
"<|\274\324<v\37)<k\35_<k\21o<\202j\256<{\16\236<\207\374\216<\203,\300"..., 32768
dumper 10786 amandabackup 4w FIFO 0,8 0t0 11581839
pipe
On the server:
# pstree -p 10781 -a -l -u
amdump,10781,amandabackup /usr/sbin/amdump --no-taper -o
maxdumpsize=1450340195 -o tapetype:DISK:length=1464990096 Data
└─driver,10785 Data --log-filename /var/lib/amanda/Data/log.20170627210058.0
--no-taper -omaxdumpsize=1450340195 -otapetype:DISK:length=1464990096
├─chunker,5040 /usr/lib64/amanda/chunker Data --log-filename
/var/lib/amanda/Data/log.20170627210058.0 -omaxdumpsize=1450340195
-otapetype:DISK:length=1464990096
│ ├─{chunker},5041
│ └─{chunker},5042
├─dumper,10786 Data --log-filename
/var/lib/amanda/Data/log.20170627210058.0 -omaxdumpsize=1450340195
-otapetype:DISK:length=1464990096
│ ├─gzip,5044 --best
│ ├─gzip,5109 --best
│ └─pigz-fast,5110 /usr/local/bin/pigz-fast
│ └─pigz,5111 --fast -p 6
│ ├─{pigz},5112
│ ├─{pigz},5113
│ ├─{pigz},5114
│ ├─{pigz},5115
│ ├─{pigz},5116
│ ├─{pigz},5117
│ └─{pigz},5118
├─dumper,10787 Data --log-filename
/var/lib/amanda/Data/log.20170627210058.0 -omaxdumpsize=1450340195
-otapetype:DISK:length=1464990096
├─dumper,10788 Data --log-filename
/var/lib/amanda/Data/log.20170627210058.0 -omaxdumpsize=1450340195
-otapetype:DISK:length=1464990096
├─dumper,10789 Data --log-filename
/var/lib/amanda/Data/log.20170627210058.0 -omaxdumpsize=1450340195
-otapetype:DISK:length=1464990096
├─dumper,10790 Data --log-filename
/var/lib/amanda/Data/log.20170627210058.0 -omaxdumpsize=1450340195
-otapetype:DISK:length=1464990096
└─dumper,10791 Data --log-filename
/var/lib/amanda/Data/log.20170627210058.0 -omaxdumpsize=1450340195
-otapetype:DISK:length=1464990096
looks like pigz is stuck on write to chuncker via local tcp socket:
[pid 5112] write(1,
"\221\247\270^n\206\220\323\326+\2128i\375\204\263B.\\/\366o\324kO\21r\316\372\351\355\302"...,
89032
lsof:
pigz 5111 amandabackup 1u IPv4 11581838 0t0 TCP
localhost:1024->localhost:54312 (ESTABLISHED)
chunker 5040 amandabackup 5u IPv4 11535329
0t0 TCP localhost:54312->localhost:1024 (ESTABLISHED)
# ss| grep 54312
tcp ESTAB 5853158 0 127.0.0.1:54312 127.0.0.1:1024
tcp ESTAB 0 303916 127.0.0.1:1024 127.0.0.1:54312
chunker log:
Tue Jun 27 21:32:33.557466893 2017: pid 5040: thd-0x1161a00: chunker: pid 5040
ruid 27120 euid 27120 version 3.4.5: start at Tue Jun 27 21:32:33 2017
Tue Jun 27 21:32:33.557573447 2017: pid 5040: thd-0x1161a00: chunker:
Arguments: Data --log-filename /var/lib/amanda/Data/log.20170627210058.0
-omaxdumpsize=1450340195 -otapetype:DISK:length=1464990096
Tue Jun 27 21:32:33.558010015 2017: pid 5040: thd-0x1161a00: chunker:
config_overrides: maxdumpsize 1450340195
Tue Jun 27 21:32:33.558026147 2017: pid 5040: thd-0x1161a00: chunker:
config_overrides: tapetype:DISK:length 1464990096
Tue Jun 27 21:32:33.558222102 2017: pid 5040: thd-0x1161a00: chunker: reading
config file /etc/amanda/Data/amanda.conf
Tue Jun 27 21:32:33.558722535 2017: pid 5040: thd-0x1161a00: chunker: reading
config file /etc/amanda/Data/../vault.conf
Tue Jun 27 21:32:33.559602025 2017: pid 5040: thd-0x1161a00: chunker: reading
config file /etc/amanda/Data/../dumptypes.conf
Tue Jun 27 21:32:33.563593170 2017: pid 5040: thd-0x1161a00: chunker: pid 5040
ruid 27120 euid 27120 version 3.4.5: rename at Tue Jun 27 21:32:33 2017
Tue Jun 27 21:32:33.564544337 2017: pid 5040: thd-0x1161a00: chunker:
Amanda::Chunker::Scribe preparing to write, max_memory 1048576
Tue Jun 27 21:32:33.564950082 2017: pid 5040: thd-0x1161a00: chunker: Starting
<Xfer@0x21f5e10 (<XferSourceDirectTCPListen@0x21f7000> ->
<XferDestHolding@0x21f6030>)>
Tue Jun 27 21:32:33.564996716 2017: pid 5040: thd-0x1161a00: chunker: Final
linkage: <XferSourceDirectTCPListen@0x21f7000> -(DIRECTTCP_LISTEN)->
<XferElementGlue@0x21f6160> -(MEM_RING)-> <XferDestHolding@0x21f6030>
Tue Jun 27 21:32:33.565011998 2017: pid 5040: thd-0x1161a00: chunker:
setup_impl: 7, 9
Tue Jun 27 21:32:33.567033638 2017: pid 5040: thd-0x1161a00: chunker: Starting
<Xfer@0x21fe4b0 (<XferSourceDirectTCPListen@0x21f70b0> ->
<XferDestBuffer@0x21fe830>)>
Tue Jun 27 21:32:33.567060700 2017: pid 5040: thd-0x1161a00: chunker: Final
linkage: <XferSourceDirectTCPListen@0x21f70b0> -(DIRECTTCP_LISTEN)->
<XferElementGlue@0x21f6290> -(PUSH_BUFFER_STATIC)-> <XferDestBuffer@0x21fe830>
Tue Jun 27 21:32:33.567069731 2017: pid 5040: thd-0x1161a00: chunker:
setup_impl: 7, 6
Tue Jun 27 21:32:33.578951794 2017: pid 5040: thd-0x21f94a0: chunker:
do_directtcp_accept: 6
Tue Jun 27 21:32:33.578981718 2017: pid 5040: thd-0x21f94a0: chunker:
read_and_push_static
Tue Jun 27 21:32:36.266560645 2017: pid 5040: thd-0x21f94a0: chunker: sending
XMSG_CRC message
Tue Jun 27 21:32:36.266588225 2017: pid 5040: thd-0x21f94a0: chunker:
read_and_push_static CRC: 6769af6b size 32768
Tue Jun 27 21:32:36.266610276 2017: pid 5040: thd-0x21f94a0: chunker:
xfer_queue_message: MSG: <XMsg@0x2ae59c001720 type=XMSG_CRC
elt=<XferSourceDirectTCPListen@0x21f70b0> version=0>
Tue Jun 27 21:32:36.266640163 2017: pid 5040: thd-0x21f94a0: chunker:
xfer_queue_message: MSG: <XMsg@0x2ae59c001500 type=XMSG_DONE
elt=<XferElementGlue@0x21f6290> version=0>
Tue Jun 27 21:32:36.267447695 2017: pid 5040: thd-0x1161a00: chunker: got 8
message from <XferSourceDirectTCPListen@0x21f70b0>
Tue Jun 27 21:32:36.270261553 2017: pid 5040: thd-0x21f9450: chunker:
do_directtcp_accept: 5
Tue Jun 27 21:32:36.270279032 2017: pid 5040: thd-0x21f9450: chunker:
read_to_mem_ring
Tue Jun 27 21:32:36.271285420 2017: pid 5040: thd-0x21f9400: chunker: Building
type FILE header of 32768-32768 bytes with name='alxdisk1ib'
disk='/export/clouds/AIRS' dumplevel=0 and blocksize=32768
chunker looks hung with futexes:
Process 5040 attached with 3 threads
[pid 5042] futex(0x21d4338, FUTEX_WAIT_PRIVATE, 13994754, NULL <unfinished ...>
[pid 5041] futex(0x21d4328, FUTEX_WAIT_PRIVATE, 13994755, NULL <unfinished ...>
[pid 5040] restart_syscall(<... resuming interrupted call ...>
(gdb) thr app all bt
Thread 3 (Thread 0x2ae58ff37700 (LWP 5041)):
#0 0x00002ae5875e2c29 in syscall () from /lib64/libc.so.6
#1 0x00002ae588c9794f in g_cond_wait () from /lib64/libglib-2.0.so.0
#2 0x00002ae58ddccbd2 in holding_thread () from /lib64/libamserver-3.4.5.so
#3 0x00002ae588c7a0f5 in g_thread_proxy () from /lib64/libglib-2.0.so.0
#4 0x00002ae5872dcdc5 in start_thread () from /lib64/libpthread.so.0
#5 0x00002ae5875e876d in clone () from /lib64/libc.so.6
Thread 2 (Thread 0x2ae590138700 (LWP 5042)):
#0 0x00002ae5875e2c29 in syscall () from /lib64/libc.so.6
#1 0x00002ae588c9794f in g_cond_wait () from /lib64/libglib-2.0.so.0
#2 0x00002ae587eca143 in read_to_mem_ring () from /lib64/libamxfer-3.4.5.so
#3 0x00002ae587ecca7f in worker_thread () from /lib64/libamxfer-3.4.5.so
#4 0x00002ae588c7a0f5 in g_thread_proxy () from /lib64/libglib-2.0.so.0
#5 0x00002ae5872dcdc5 in start_thread () from /lib64/libpthread.so.0
#6 0x00002ae5875e876d in clone () from /lib64/libc.so.6
Thread 1 (Thread 0x2ae585fe2540 (LWP 5040)):
#0 0x00002ae5875dde2d in poll () from /lib64/libc.so.6
#1 0x00002ae588c5504c in g_main_context_iterate.isra.24 () from
/lib64/libglib-2.0.so.0
#2 0x00002ae588c5516c in g_main_context_iteration () from /lib64/libglib-2.0.so.0
#3 0x00002ae588110515 in event_loop_wait () from /lib64/libamanda-3.4.5.so
#4 0x00002ae58eaea900 in _wrap_run_c ()
from /usr/lib64/perl5/vendor_perl/auto/Amanda/MainLoop/libMainLoop.so
#5 0x00002ae58629042f in Perl_pp_entersub (my_perl=0x1138010) at pp_hot.c:2778
#6 0x00002ae586288ba6 in Perl_runops_standard (my_perl=0x1138010) at run.c:41
#7 0x00002ae5862259a5 in S_run_body (oldscope=<optimized out>,
my_perl=<optimized out>)
at perl.c:2402
#8 perl_run (my_perl=0x1138010) at perl.c:2320
#9 0x0000000000400d99 in main (argc=7, argv=0x7ffe10a42248,
env=0x7ffe10a42288) at perlmain.c:120
Looks like poll() is listening on fd 0 and 3:
chunker 5040 amandabackup 0u unix 0xffff88003664f800 0t0
11600703 socket
chunker 5040 amandabackup 3u a_inode 0,9 0
6935 [eventfd]
Did manage to dump 428GB before hanging:
-rw-------. 1 amandabackup disk 428G Jun 27 23:14
/export/amanda/Data/slot9/holding/20170627210058/alxdisk1ib._export_clouds_AIRS.0.tmp
Can I turn on more chunker debugging?
Thanks.
--
Orion Poplawski
Technical Manager 720-772-5637
NWRA, Boulder/CoRA Office FAX: 303-415-9702
3380 Mitchell Lane [email protected]
Boulder, CO 80301 http://www.nwra.com