Re: tar crashing?, chunker hanging with 3.4.5

The main thread (1) never poll for the compressed data.
The thread 2 is expected to read the data.

Do some of the data was written to the holding file?

Can you set debug-chunker to 9 in amanda.conf and retry?
If compile amanda yourself, can you compile it with the '-g' flag to cc, 
it will make the stack trace a lot more useful.

The chunker is waiting for something, t doesn't mean the bug is in the 
chunker.
It tar died, that information should have go to amgtar. sendbackup, 
dumper and chunker.
Can you also post the amgtar, sendbackup and duper debug files?

Jean-Louis

On 19/09/17 01:17 PM, Orion Poplawski wrote:
> 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 
> <http://www.nwra.com>
>
This message is the property of CARBONITE, INC. and may contain confidential or privileged information.
If this message has been delivered to you by mistake, then do not copy or deliver this message to anyone.  Instead, destroy it and notify me by reply e-mail