Hi,
If you run tar by hand on the DLE does it finish? After how much time?
Kind regards
Jose M Calhariz
On Wed, Jun 15, 2022 at 09:50:11AM -0600, Orion Poplawski wrote:
> On 6/15/22 09:38, Orion Poplawski wrote:
> > Recently the backup of a particular DLE has started hanging consistently. I
> > don't see any recent changes on the server except possibly a change from
> > kernel 3.10.0-1160.62.1.el7 to 3.10.0-1160.66.1.el7 on Jun 2nd, but the
> > problem didn't start until June 6th.
> >
> > The tar command is stuck trying to write out the name of the directory to
> > amgtar:
> >
> > root 11321 11315 33 Jun14 ? 03:55:46 /usr/bin/tar --create
> > --verbose --verbose --block-number --file - --directory
> > /export/backup/rufous
> > --no-check-device --listed-incremental
> > /var/lib/amanda/gnutar-lists/saga_export_backup_rufous_0.new
> > --ignore-failed-read --totals --exclude-from
> > /var/log/amanda/amgtar._export_backup_rufous.20220614211711.exclude .
> > root 11432 11427 42 Jun14 ? 03:57:48 /usr/bin/tar --create
> > --verbose --verbose --block-number --file - --directory
> > /export/backup/rufous
> > --no-check-device --listed-incremental
> > /var/lib/amanda/gnutar-lists/saga_export_backup_rufous_0.new
> > --ignore-failed-read --totals --exclude-from
> > /var/log/amanda/amgtar._export_backup_rufous.20220614234714.exclude .
> >
> > # strace -f -s 500 -p 11321
> > strace: Process 11321 attached
> > write(2, " ./export/home/orion-admin/ansible-boulder/.git/objects/db/", 59
> >
> > # strace -f -s 500 -p 11432
> > strace: Process 11432 attached
> > write(2, " ./export/home/orion-admin/ansible-boulder/.git/objects/db/", 59
> >
> > amgtar is stuck writing output to amandad:
> >
> > # strace -s 200 -p 11427
> > strace: Process 11427 attached
> > write(4, "e_pylibssh.libs/\ndrwxr-x--- orion-admin/orion-admin 0
> > 2022-05-23 17:31
> > ./export/home/orion-admin/.local/lib/python3.8/site-packages/bcrypt/\ndrwxr-x---
> > orion-admin/orion-admin 0 2022-05-23 17:3"..., 4096
> >
> >
> > amgtar debug has:
> >
> > Tue Jun 14 23:47:14.104627682 2022: pid 11427: ??-amgtar : pid 11427 ruid > > 0
> > euid 27120 ppid 11418 version 3.6.0: start at Tue Jun 14 23:47:14 2022
> > Tue Jun 14 23:47:14.104731978 2022: pid 11427: ??-amgtar : version 3.6.0
> > Tue Jun 14 23:47:14.104957990 2022: pid 11427: ??-amgtar : state_stream:
> > 156
> > Tue Jun 14 23:47:14.110961812 2022: pid 11427: ??-amgtar : pid 11427 ruid > > 0
> > euid 27120 ppid 11418 version 3.6.0: rename at Tue Jun 14 23:47:14 2022
> > Tue Jun 14 23:47:14.110991922 2022: pid 11427: ??-amgtar : GNUTAR-PATH
> > /bin/tar
> > Tue Jun 14 23:47:14.111004028 2022: pid 11427: ??-amgtar : GNUTAR-LISTDIR
> > /var/lib/amanda/gnutar-lists
> > Tue Jun 14 23:47:14.111013955 2022: pid 11427: ??-amgtar :
> > ONE-FILE-SYSTEM no
> > Tue Jun 14 23:47:14.111023583 2022: pid 11427: ??-amgtar : SPARSE yes
> > Tue Jun 14 23:47:14.111033039 2022: pid 11427: ??-amgtar : NO-UNQUOTE no
> > Tue Jun 14 23:47:14.111042417 2022: pid 11427: ??-amgtar : ATIME-PRESERVE
> > no
> > Tue Jun 14 23:47:14.111051865 2022: pid 11427: ??-amgtar : ACLS no
> > Tue Jun 14 23:47:14.111061481 2022: pid 11427: ??-amgtar : SELINUX no
> > Tue Jun 14 23:47:14.111121121 2022: pid 11427: ??-amgtar : XATTRS no
> > Tue Jun 14 23:47:14.111130900 2022: pid 11427: ??-amgtar : CHECK-DEVICE no
> > Tue Jun 14 23:47:14.111140474 2022: pid 11427: ??-amgtar : SIZE ^ *Total
> > bytes written: [0-9][0-9]*
> > Tue Jun 14 23:47:14.111150269 2022: pid 11427: ??-amgtar : IGNORE :
> > Directory is new$
> > Tue Jun 14 23:47:14.111159886 2022: pid 11427: ??-amgtar : IGNORE :
> > Directory has been renamed
> > Tue Jun 14 23:47:14.111169511 2022: pid 11427: ??-amgtar : NORMAL ^could
> > not
> > open conf file
> > Tue Jun 14 23:47:14.111179212 2022: pid 11427: ??-amgtar : NORMAL
> > ^Elapsed time:
> > Tue Jun 14 23:47:14.111309287 2022: pid 11427: ??-amgtar : NORMAL
> > ^Throughput
> > Tue Jun 14 23:47:14.111321160 2022: pid 11427: ??-amgtar : NORMAL :
> > directory is on a different filesystem; not dumped
> > Tue Jun 14 23:47:14.111331690 2022: pid 11427: ??-amgtar : NORMAL : socket
> > ignored$
> > Tue Jun 14 23:47:14.111342121 2022: pid 11427: ??-amgtar : NORMAL : File
> > .*
> > shrunk by [0-9][0-9]* bytes, padding with zeros
> > Tue Jun 14 23:47:14.111397543 2022: pid 11427: ??-amgtar : NORMAL : Cannot
> > add file .*: No such file or directory$
> > Tue Jun 14 23:47:14.111407572 2022: pid 11427: ??-amgtar : NORMAL : Error
> > exit delayed from previous errors
> > Tue Jun 14 23:47:14.111417962 2022: pid 11427: ??-amgtar : ERROR amgtar:
> > error
> > Tue Jun 14 23:47:14.114473250 2022: pid 11427: ??-amgtar : Spawning
> > "/bin/tar /bin/tar -x --no-check-device -f -" in pipeline
> > Tue Jun 14 23:47:14.124455374 2022: pid 11431: ??-amgtar : Executing:
> > /bin/tar '--version'
> > Tue Jun 14 23:47:14.126144343 2022: pid 11427: ??-amgtar : Spawning
> > "/usr/bin/tar /usr/bin/tar --create --verbose --verbose --block-number
> > --file
> > - --directory /export/backup/rufous --no-check-device --listed-incremental
> > /var/lib/amanda/gnutar-lists/saga_export_backup_rufous_0.new
> > --ignore-failed-read --totals --exclude-from
> > /var/log/amanda/amgtar._export_backup_rufous.20220614234714.exclude ." in
> > pipeline
> >
> > amandad debug has:
> >
> > Tue Jun 14 23:47:14.049156625 2022: pid 11417: ??-amandad : sending REP
> > pkt:
> > <<<<<
> > CONNECT DATA 499999 MESG 499998 INDEX 499997 STATE 499996
> > OPTIONS features=ffffffff9efefbfffffffffffffff3fffbf79f00;
> >>>>>>
> > Tue Jun 14 23:47:14.049312862 2022: pid 11417: ??-amandad : received ACK
> > pkt:
> > <<<<<
> >>>>>>
> > Tue Jun 14 23:47:14.049335184 2022: pid 11417: ??-amandad : opening
> > security
> > stream (0x5567229f24f8) for fd 150
> > Tue Jun 14 23:47:14.049351969 2022: pid 11417: ??-amandad : opening
> > security
> > stream (0x5567229f2528) for fd 151
> > Tue Jun 14 23:47:14.049369455 2022: pid 11417: ??-amandad : opening
> > security
> > stream (0x5567229f2558) for fd 152
> > Tue Jun 14 23:47:14.049385426 2022: pid 11417: ??-amandad : opening
> > security
> > stream (0x5567229f2588) for fd 153
> > Tue Jun 14 23:47:14.049401254 2022: pid 11417: ??-amandad :
> > security_close(handle=0x5567229e9780, driver=0x7f40c660f540 (BSDTCP))
> > Tue Jun 14 23:47:14.049414836 2022: pid 11417: ??-amandad :
> > security_stream_close(0x5567229e98d0)
> > Tue Jun 14 23:47:14.049631091 2022: pid 11417: ??-amandad : ignoring close
> > stream 2
> > Tue Jun 14 23:47:14.096232682 2022: pid 11417: ??-amandad +9 :
> > shm_ring_consumer_set_size
> > Tue Jun 14 23:47:14.096611706 2022: pid 11417: ??-amandad +9 :
> > shm_ring_to_security_stream
> > Wed Jun 15 02:17:15.145660919 2022: pid 11417: ??-amandad :
> > stream_read_callback: data is still flowing
> > Wed Jun 15 02:17:15.154334223 2022: pid 11417: ??-amandad :
> > security_stream_seterr(0x556722a0bc10, EOF)
> > Wed Jun 15 02:17:15.154365691 2022: pid 11417: ??-amandad :
> > process_writenetfd 13: 0
> >
> > amandad seems to stuck in futex:
> >
> > # strace -f -p 11417
> > strace: Process 11417 attached with 2 threads
> > [pid 11417] futex(0x7f40c0d2a9d0, FUTEX_WAIT, 11426, NULL <unfinished ...>
> > [pid 11426] restart_syscall(<... resuming interrupted read ...>
> >
> > So a I guess a resource lock race of some sort. Interesting that it is so
> > consistent though.
> >
> > gdb reports:
> >
> > Thread 2 (Thread 0x7f40c0d2a700 (LWP 11426)):
> > #0 0x00007f40c433fd2f in do_futex_wait () from /lib64/libpthread.so.0
> > #1 0x00007f40c433fe07 in __new_sem_wait_slow () from /lib64/libpthread.so.0
> > #2 0x00007f40c433fea5 in sem_timedwait () from /lib64/libpthread.so.0
> > #3 0x00007f40c63ca785 in shm_ring_sem_wait
> > (shm_ring=shm_ring@entry=0x5567229fae60, sem=0x7f40c6a85000) at
> > shm-ring.c:231
> > #4 0x00007f40c63cace6 in shm_ring_to_security_stream
> > (shm_ring=0x5567229fae60, netfd=0x556722a0bc10, crc=0x0) at shm-ring.c:410
> > #5 0x0000556720fdad0b in shm_ring_thread (cookie=0x5567229f24f8) at
> > amandad.c:1577
> > #6 0x00007f40c5a7d5c5 in g_thread_proxy () from /lib64/libglib-2.0.so.0
> > #7 0x00007f40c4339ea5 in start_thread () from /lib64/libpthread.so.0
> > #8 0x00007f40c4062b0d in clone () from /lib64/libc.so.6
> >
> > Thread 1 (Thread 0x7f40c6a69840 (LWP 11417)):
> > #0 0x00007f40c433b017 in pthread_join () from /lib64/libpthread.so.0
> > #1 0x00007f40c5a9afc7 in g_system_thread_wait () from
> > /lib64/libglib-2.0.so.0
> > #2 0x00007f40c5a7da25 in g_thread_join () from /lib64/libglib-2.0.so.0
> > #3 0x0000556720fdbfd5 in process_writenetfd (cookie=0x5567229f24f8,
> > buf=<optimized out>, size=<optimized out>) at amandad.c:1609
> > #4 0x00007f40c63c6fc0 in sec_tcp_conn_read_callback (cookie=0x5567229e79b0)
> > at security-util.c:2474
> > #5 0x00007f40c63b80de in event_handle_callback (user_ptr=0x5567229e7f50) at
> > event.c:118
> > #6 0x00007f40c5a56119 in g_main_context_dispatch () from
> > /lib64/libglib-2.0.so.0
> > #7 0x00007f40c5a56478 in g_main_context_iterate.isra.19 () from
> > /lib64/libglib-2.0.so.0
> > #8 0x00007f40c5a5652c in g_main_context_iteration () from
> > /lib64/libglib-2.0.so.0
> > #9 0x00007f40c63b7fdd in event_loop_wait (wait_eh=0x0, nonblock=0,
> > return_when_empty=1) at event.c:427
> > #10 0x00007f40c63b841e in event_loop (nonblock=<optimized out>) at
> > event.c:328
> > #11 0x0000556720fd9d76 in main (argc=5, argv=0x7ffcbd7f2508) at
> > amandad.c:535
> >
> > (gdb) list
> > 1604 full_write(dh->fd_write, buf, (size_t)size);
> > 1605 } else {
> > 1606 g_debug("process_writenetfd %d: %zd", dh->fd_write, size);
> > 1607 aclose(dh->fd_write);
> > 1608 if (as->thread && dh->shm_ring) {
> > 1609 g_thread_join(as->thread);
> > 1610 close_consumer_shm_ring(dh->shm_ring);
> > 1611 dh->shm_ring = NULL;
> > 1612 as->thread = NULL;
> > 1613 }
> >
> > So it looks like a write to fd 13 failed and now it's trying to join the
> > other
> > thread but the other thread is waiting for something else?
> >
> > Not sure what fd 13 was.
> >
> > amdump:
> >
> > driver: hdisk-state time 13625.015 hdisk 0: free 897061131 dumpers 2
> > driver: result time 13625.015 from chunker1: FAILED 01-00002 "Got empty
> > header"
> > driver: send-cmd time 13625.015 to chunker1: QUIT
> > dumper: kill index command
> > driver: state time 13625.017 free kps: 7480 space: 897061131 taper: down
> > idle-dumpers: 4 qlen runq: 31 directq: 0 roomq: 0 wakeup: 0 driver-idle:
> > no-bandwidth
> > driver: interface-state time 13625.017 if default: free 7480
> > driver: hdisk-state time 13625.017 hdisk 0: free 897061131 dumpers 2
> > driver: result time 13625.017 from dumper1: FAILED 01-00002 "[data timeout]"
> >
> >
> > driver: requeue dump time 13625.024 saga /export/backup/rufous
> > 20220614200007
> > driver: started chunker1 pid 11409
> > driver: send-cmd time 13625.043 to chunker1: START 20220614200007
> > driver: send-cmd time 13625.043 to chunker1: SHM-WRITE 01-00025
> > /export/amanda/Data/data/holding/20220614200007/saga._export_backup_rufous.0
> > saga ffffffff9efefbfffffffffffffff3fffbf79f00 /export/backup/rufous 0
> > 20220614200007 9007199254740896 APPLICATION 91707744
> > |;auth=BSDTCP;comp-cust=/usr/local/bin/zstd-amanda;index;exclude-list=/usr/local/lib/amanda/exclude.gtar;
> > driver: state time 13625.043 free kps: 7480 space: 897061131 taper: down
> > idle-dumpers: 4 qlen runq: 31 directq: 0 roomq: 0 wakeup: 0 driver-idle:
> > no-bandwidth
> > driver: interface-state time 13625.043 if default: free 7480
> > driver: hdisk-state time 13625.043 hdisk 0: free 897061131 dumpers 2
> > driver: state time 13625.525 free kps: 7480 space: 897061131 taper: down
> > idle-dumpers: 4 qlen runq: 31 directq: 0 roomq: 0 wakeup: 0 driver-idle:
> > no-bandwidth
> > driver: interface-state time 13625.525 if default: free 7480
> > driver: hdisk-state time 13625.525 hdisk 0: free 897061131 dumpers 2
> > driver: result time 13625.525 from chunker1: SHM-NAME 01-00025 45615
> > /amanda_shm_control-11409-0
> > driver: send-cmd time 13625.525 to dumper1: SHM-DUMP 01-00025 45615 NULL 2
> > saga ffffffff9efefbfffffffffffffff3fffbf79f00 /export/backup/rufous
> > NODEVICE 0
> > 1970:1:1:0:0:0 amgtar "" "" "" "" "" "" "" 1 "" "" BSDTCP AMANDA
> > /amanda_shm_control-11409-0 20 |" <auth>BSDTCP</auth>\n
> > <compress>CUSTOM<custom-compress-program>/usr/local/bin/zstd-amanda</custom-compress-program>\n
> > </compress>\n <record>YES</record>\n <index>YES</index>\n
> > <datapath>AMANDA</datapath>\n <exclude>\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>one-file-system</name>\n <value>no</value>\n
> > </property>\n <property>\n <name>check-device</name>\n
> > <value>NO</value>\n </property>\n </backup-program>\n"
> > driver: state time 14304.799 free kps: 7480 space: 897061131 taper: down
> > idle-dumpers: 4 qlen runq: 31 directq: 0 roomq: 0 wakeup: 0 driver-idle:
> > no-bandwidth
> >
> >
> > driver: hdisk-state time 22627.693 hdisk 0: free 889377437 dumpers 1
> > driver: result time 22627.694 from chunker1: FAILED 01-00025 "Got empty
> > header"
> > driver: send-cmd time 22627.694 to chunker1: QUIT
> > driver: state time 22627.694 free kps: 54377 space: 889377437 taper: down
> > idle-dumpers: 5 qlen runq: 24 directq: 0 roomq: 0 wakeup: 0 driver-idle:
> > no-bandwidth
> > driver: interface-state time 22627.694 if default: free 54377
> > driver: hdisk-state time 22627.694 hdisk 0: free 889377437 dumpers 1
> > driver: result time 22627.694 from dumper1: FAILED 01-00025 "[data timeout]"
> >
> >
> >
>
> dumper debug:
>
> Tue Jun 14 23:47:14.050811639 2022: pid 26755: ??-dumper : execute:
> /bin/gzip --best
> Tue Jun 14 23:47:14.051401155 2022: pid 26755: ??-dumper : shm_ring_link
> /amanda_shm_control-11409-0
> Tue Jun 14 23:47:14.051494727 2022: pid 26755: ??-dumper : am_sem_open
> 0x2b1d7a1a0000 1
> Tue Jun 14 23:47:14.051530731 2022: pid 26755: ??-dumper : am_sem_open
> 0x2b1d7a1a1000 1
> Tue Jun 14 23:47:14.051559966 2022: pid 26755: ??-dumper : am_sem_open
> 0x2b1d7a1a2000 1
> Tue Jun 14 23:47:14.051588105 2022: pid 26755: ??-dumper : am_sem_open
> 0x2b1d7a1a3000 1
> Tue Jun 14 23:47:14.051643504 2022: pid 26755: ??-dumper : ignoring close
> stream 2
> Tue Jun 14 23:47:14.096077879 2022: pid 26755: ??-dumper : process_dumpline:
> sendbackup: info BACKUP=APPLICATION
> Tue Jun 14 23:47:14.096121639 2022: pid 26755: ??-dumper : process_dumpline:
> sendbackup: info APPLICATION=amgtar
> Tue Jun 14 23:47:14.096139130 2022: pid 26755: ??-dumper : process_dumpline:
> sendbackup: info RECOVER_CMD=/usr/lib64/amanda/application/amgtar restore
> [./file-to-restore]+
> Tue Jun 14 23:47:14.096153942 2022: pid 26755: ??-dumper : process_dumpline:
> sendbackup: info COMPRESS_SUFFIX=.gz
> Tue Jun 14 23:47:14.096167822 2022: pid 26755: ??-dumper : process_dumpline:
> sendbackup: info end
>
> Wed Jun 15 02:17:15.144317671 2022: pid 26755: ??-dumper :
> security_stream_close(0x55f97d935b00)
> Wed Jun 15 02:17:15.144372747 2022: pid 26755: ??-dumper : tcpm_send_token:
> data is still flowing
> Wed Jun 15 02:17:15.144990640 2022: pid 26755: ??-dumper :
> security_stream_close(0x55f97d93dba0)
> Wed Jun 15 02:17:15.145033854 2022: pid 26755: ??-dumper :
> security_stream_close(0x55f97d945c40)
> Wed Jun 15 02:17:15.145067531 2022: pid 26755: ??-dumper :
> security_stream_close(0x55f97d94dce0)
> Wed Jun 15 02:17:15.145099749 2022: pid 26755: ??-dumper : stop_dump:
> cancelling shm-ring-producer
> Wed Jun 15 02:17:15.147321610 2022: pid 26755: ??-dumper : putresult: 10
> FAILED 01-00025 "[data timeout]"
>
> Wed Jun 15 02:17:15.148946983 2022: pid 26755: ??-dumper :
> close_producer_shm_ring sem_close(sem_write 0x2b1d7a1a0000
> Wed Jun 15 02:17:15.148971073 2022: pid 26755: ??-dumper : am_sem_close
> 0x2b1d7a1a0000 0
> Wed Jun 15 02:17:15.149000272 2022: pid 26755: ??-dumper : am_sem_close
> 0x2b1d7a1a2000 0
> Wed Jun 15 02:17:15.149024668 2022: pid 26755: ??-dumper : am_sem_close
> 0x2b1d7a1a1000 0
> Wed Jun 15 02:17:15.149048448 2022: pid 26755: ??-dumper : am_sem_close
> 0x2b1d7a1a3000 0
>
>
> chunker:
>
> Tue Jun 14 23:47:12.974488957 2022: pid 11409: dmn-chunker : chunker/driver
> << START 20220614200007
> Tue Jun 14 23:47:12.974676300 2022: pid 11409: dmn-chunker :
> Amanda::Chunker::Scribe: starting
> Tue Jun 14 23:47:12.974715240 2022: pid 11409: dmn-chunker : chunker/driver
> << SHM-WRITE 01-00025
> /export/amanda/Data/data/holding/20220614200007/saga._export_backup_rufous.0
> saga ffffffff9efefbfffffffffffffff3fffbf79f00 /export/backup/rufous 0
> 20220614200007 9007199254740896 APPLICATION 91707744
> |;auth=BSDTCP;comp-cust=/usr/local/bin/zstd-amanda;index;exclude-list=/usr/local/lib/amanda/exclude.gtar;
> Tue Jun 14 23:47:12.975114398 2022: pid 11409: dmn-chunker :
> Amanda::Chunker::Scribe preparing to write, max_memory 1048576
> Tue Jun 14 23:47:12.975644139 2022: pid 11409: dmn-chunker : Starting
> <Xfer@0x1cd3bb0 (<XferSourceShmRing@0x1cd5000> ->
> <XferDestHolding@0x1cd4030>)>
> Tue Jun 14 23:47:12.975679601 2022: pid 11409: dmn-chunker : Final linkage:
> <XferSourceShmRing@0x1cd5000> -(SHM_RING)-> <XferDestHolding@0x1cd4030>
> Tue Jun 14 23:47:12.975701215 2022: pid 11409: dmn-chunker : shm_ring_create
> Tue Jun 14 23:47:12.976642670 2022: pid 11409: dmn-chunker : am_sem_create
> 0x2b27e1ba8000 1
> Tue Jun 14 23:47:12.976712858 2022: pid 11409: dmn-chunker : am_sem_create
> 0x2b27e1ba9000 1
> Tue Jun 14 23:47:12.976783056 2022: pid 11409: dmn-chunker : am_sem_create
> 0x2b27e1baa000 1
> Tue Jun 14 23:47:12.976848562 2022: pid 11409: dmn-chunker : am_sem_create
> 0x2b27e1bab000 1
> Tue Jun 14 23:47:12.976863381 2022: pid 11409: dmn-chunker : shm_data:
> /amanda_shm_data-11409-5
> Tue Jun 14 23:47:12.976874375 2022: pid 11409: dmn-chunker : sem_write:
> /amanda_sem_write-11409-1
> Tue Jun 14 23:47:12.976884993 2022: pid 11409: dmn-chunker : sem_read:
> /amanda_sem_read-11409-2
> Tue Jun 14 23:47:12.976895476 2022: pid 11409: dmn-chunker : sem_ready:
> /amanda_sem_ready-11409-3
> Tue Jun 14 23:47:12.976905865 2022: pid 11409: dmn-chunker : sem_start:
> /amanda_sem_start-11409-4
> Tue Jun 14 23:47:12.977055615 2022: pid 11409: dmn-chunker +1 : XDH: (this
> is the holding thread)
> Tue Jun 14 23:47:12.977099738 2022: pid 11409: dmn-chunker +1 :
> shm_ring_consumer_set_size
> Tue Jun 14 23:47:12.977515425 2022: pid 11409: dmn-chunker : Starting
> <Xfer@0x1cdcf20 (<XferSourceDirectTCPListen@0x1cd50b0> ->
> <XferDestBuffer@0x1cdd030>)>
> Tue Jun 14 23:47:12.977559777 2022: pid 11409: dmn-chunker : Final linkage:
> <XferSourceDirectTCPListen@0x1cd50b0> -(DIRECTTCP_LISTEN)->
> <XferElementGlue@0x1cd4160> -(PUSH_BUFFER_STATIC)-> <XferDestBuffer@0x1cdd030>
> Tue Jun 14 23:47:12.977577998 2022: pid 11409: dmn-chunker : setup_impl: 7,
> 6
> Tue Jun 14 23:47:12.979502757 2022: pid 11409: dmn-chunker : chunker/driver
> >> SHM-NAME 01-00025 45615 /amanda_shm_control-11409-0
> Tue Jun 14 23:47:12.989125985 2022: pid 11409: dmn-chunker +2 :
> do_directtcp_accept: 9
> Tue Jun 14 23:47:12.989168588 2022: pid 11409: dmn-chunker +2 :
> read_and_push_static
>
> Wed Jun 15 02:17:15.145146389 2022: pid 11409: dmn-chunker +1 :
> shm_ring_consumer_set_size: cancelled
> Wed Jun 15 02:17:15.145291264 2022: pid 11409: dmn-chunker +2 : sending
> XMSG_CRC message
> Wed Jun 15 02:17:15.145326872 2022: pid 11409: dmn-chunker +2 :
> read_and_push_static CRC: 00000000 size 0
> Wed Jun 15 02:17:15.145360671 2022: pid 11409: dmn-chunker +2 :
> xfer_queue_message: MSG: <XMsg@0x2b27f0009510 type=XMSG_CRC
> elt=<XferSourceDirectTCPListen@0x1cd50b0> version=0>
> Wed Jun 15 02:17:15.145417700 2022: pid 11409: dmn-chunker +2 :
> xfer_queue_message: MSG: <XMsg@0x2b27f0001500 type=XMSG_DONE
> elt=<XferElementGlue@0x1cd4160> version=0>
> Wed Jun 15 02:17:15.146643567 2022: pid 11409: dmn-chunker : got 8 message
> from <XferSourceDirectTCPListen@0x1cd50b0>
> Wed Jun 15 02:17:15.147215294 2022: pid 11409: dmn-chunker : chunker/driver
> >> FAILED 01-00025 "Got empty header"
> Wed Jun 15 02:17:15.149430652 2022: pid 11409: dmn-chunker : chunker/driver
> << QUIT
> Wed Jun 15 02:17:15.149952931 2022: pid 11409: dmn-chunker :
> Amanda::Chunker::Scribe: quitting
> Wed Jun 15 02:17:15.150185329 2022: pid 11409: dmn-chunker : ru_utime :
> 0.285080s/0.080034s total user/system-cpu time
> Wed Jun 15 02:17:15.150203902 2022: pid 11409: dmn-chunker : ru_maxrss :
> 106.457MB max memory used
> Wed Jun 15 02:17:15.150215753 2022: pid 11409: dmn-chunker : ru_minflt :
> 6493/10 x remap/full page fetch
> Wed Jun 15 02:17:15.150239864 2022: pid 11409: dmn-chunker : ru_inblock :
> 4032/32 x fs real reads/writes
> Wed Jun 15 02:17:15.150255326 2022: pid 11409: dmn-chunker : ru_nvcsw :
> 55/5 x task context-yields/switches
> Wed Jun 15 02:17:15.150486971 2022: pid 11409: dmn-chunker : pid 11409
> finish time Wed Jun 15 02:17:15 2022
>
> driver:
>
> Wed Jun 15 02:17:15.148311178 2022: pid 26752: ??-driver : driver: result
> time 22627.694 from chunker1: FAILED 01-00025 "Got empty header"
> Wed Jun 15 02:17:15.148408571 2022: pid 26752: ??-driver : driver: send-cmd
> time 22627.694 to chunker1: QUIT
> Wed Jun 15 02:17:15.148528011 2022: pid 26752: ??-driver : driver: result
> time 22627.694 from dumper1: FAILED 01-00025 "[data timeout]"
>
--
--
Somente os grandes homens têm o direito de possuir grandes defeitos
--La Rochefoucauld
signature.asc
Description: PGP signature
