Re: tar crashing?, chunker hanging with 3.4.5

On 06/28/2017 11:46 AM, Orion Poplawski wrote:
> 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.

This is happening pretty regularly - once or twice a week.

At this point I think it is chunker that is getting stuck.  Large amounts of
data is stuck being written to it:

netstat shows:

Proto Recv-Q Send-Q Local Address           Foreign Address         State
tcp        0 267308 localhost:1024          localhost:45755         ESTABLISHED
tcp   5871739      0 localhost:45755         localhost:1024          ESTABLISHED


chunker 24975 amandabackup    0u     unix 0xffff8801014cbc00         0t0
56399951 socket
chunker 24975 amandabackup    1u     unix 0xffff8801014cbc00         0t0
56399951 socket
chunker 24975 amandabackup    2w      REG             253,56      328897
10517668 /var/lib/amanda/Data/amdump.20170918210023
chunker 24975 amandabackup    3u  a_inode                0,9           0
7003 [eventfd]
chunker 24975 amandabackup    4u      REG             253,41 66304638976
108809
/export/amanda/Data/slot3/holding/20170918210023/csdisk1ib._export_cora3_lindsey.0.tmp
chunker 24975 amandabackup    5u     IPv4           56390190         0t0
TCP localhost:45755->localhost:1024 (ESTABLISHED)
chunker 24975 amandabackup    7r      REG              253,3       68654
1062575 /usr/share/perl5/vendor_perl/JSON.pm
chunker 24975 amandabackup   10w      REG             253,55        8476
51001 /var/log/amanda/server/Data/chunker.20170918233723003.debug


(gdb) thr app all bt

Thread 3 (Thread 0x2ae455d67700 (LWP 25000)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00002ae44ea7289f in g_cond_wait (cond=0x294f120, mutex=0x294f110) at
gthread-posix.c:1395
#2  0x00002ae453bfcbd2 in holding_thread () from /lib64/libamserver-3.4.5.so
#3  0x00002ae44ea54f35 in g_thread_proxy (data=0x2974400) at gthread.c:784
#4  0x00002ae44d0b3e25 in start_thread (arg=0x2ae455d67700) at
pthread_create.c:308
#5  0x00002ae44d3c034d in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 2 (Thread 0x2ae455f68700 (LWP 25004)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00002ae44ea7289f in g_cond_wait (cond=0x294f130, mutex=0x294f110) at
gthread-posix.c:1395
#2  0x00002ae44dca3143 in read_to_mem_ring () from /lib64/libamxfer-3.4.5.so
#3  0x00002ae44dca5a7f in worker_thread () from /lib64/libamxfer-3.4.5.so
#4  0x00002ae44ea54f35 in g_thread_proxy (data=0x2974450) at gthread.c:784
#5  0x00002ae44d0b3e25 in start_thread (arg=0x2ae455f68700) at
pthread_create.c:308
#6  0x00002ae44d3c034d in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Thread 1 (Thread 0x2ae44bdb9540 (LWP 24975)):
#0  0x00002ae44d3b5a3d in poll () at ../sysdeps/unix/syscall-template.S:81
#1  0x00002ae44ea2e7ac in g_main_context_poll (priority=2147483647, n_fds=2,
fds=0x295bd90,
    timeout=-1, context=0x295aa70) at gmain.c:4226
#2  g_main_context_iterate (context=context@entry=0x295aa70, block=block@entry=1,
    dispatch=dispatch@entry=1, self=<optimized out>) at gmain.c:3922
#3  0x00002ae44ea2e8cc in g_main_context_iteration (context=0x295aa70,
may_block=1)
    at gmain.c:3988
#4  0x00002ae44dee9515 in event_loop_wait () from /lib64/libamanda-3.4.5.so
#5  0x00002ae45491a900 in _wrap_run_c ()
   from /usr/lib64/perl5/vendor_perl/auto/Amanda/MainLoop/libMainLoop.so
#6  0x00002ae44c06742f in Perl_pp_entersub () from
/usr/lib64/perl5/CORE/libperl.so
#7  0x00002ae44c05fba6 in Perl_runops_standard () from
/usr/lib64/perl5/CORE/libperl.so
#8  0x00002ae44bffc9a5 in perl_run () from /usr/lib64/perl5/CORE/libperl.so
#9  0x0000000000400d99 in main ()
(gdb) list
76      #else
77
78      /* This is a "normal" system call stub: if there is an error,
79         it returns -1 and sets errno.  */
80
81      T_PSEUDO (SYSCALL_SYMBOL, SYSCALL_NAME, SYSCALL_NARGS)
82              ret
83      T_PSEUDO_END (SYSCALL_SYMBOL)
84
85      #endif
(gdb) up
#1  0x00002ae44ea2e7ac in g_main_context_poll (priority=2147483647, n_fds=2,
fds=0x295bd90,
    timeout=-1, context=0x295aa70) at gmain.c:4226
4226          if ((*poll_func) (fds, n_fds, timeout) < 0 && errno != EINTR)
(gdb) print fds
$1 = (GPollFD *) 0x295bd90
(gdb) print *fds
$2 = {fd = 0, events = 1, revents = 0}
(gdb) print timeout
$3 = -1
(gdb) print n_fds
$4 = 2
(gdb) print fds[1]
$5 = {fd = 3, events = 1, revents = 0}


So it looks like poll() is waiting for fd 0 and fd 3, but not fd 5 which is
where the compressed data is coming from.

#4  0x00002ae44dee9515 in event_loop_wait (wait_eh=0x0, nonblock=0,
return_when_empty=0)
    at event.c:427
427             g_main_context_iteration(NULL, !nonblock);
(gdb) list
422                 break;
423
424             /* Do an iteration */
425             /* Relese the lock before running an iteration */
426             g_static_mutex_unlock(&event_mutex);
427             g_main_context_iteration(NULL, !nonblock);
428             g_static_mutex_lock(&event_mutex);
429
430             /* stop if we're told to */
431             if (!return_when_empty && stop)


-- 
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