On 6/17/22 04:25, Jose M Calhariz wrote:
Hi,


If you run tar by hand on the DLE does it finish?  After how much time?

Thanks for the suggestion. That made me notice that it was bogging down dealing with a *very* deep directory that had been created by a buggy process going into infinite recursion. Removing that appears to have fixed the dump.

Still seems like there is an issue with amanda not cleaning up properly from the timeout condition though.


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






--
Orion Poplawski
he/him/his  - surely the least important thing about me
IT Systems Manager                         720-772-5637
NWRA, Boulder/CoRA Office             FAX: 303-415-9702
3380 Mitchell Lane                       or...@nwra.com
Boulder, CO 80301                 https://www.nwra.com/

Attachment: smime.p7s
Description: S/MIME Cryptographic Signature

Reply via email to