Re: amrecover usage with chg-robot

Am 27.05.22 um 17:30 schrieb Nathan Stratton Treadway:

> Ah, so euxvo_crypt is run by the amidxtaped process rather than by the
> amrecover process itself.
> 
> What does strace show amrecover is doing during this period?
> 
> And "ps -ef" shows that the openssl process is still alive (i.e. not
> defunct).  What does "strace" show on that process.  If you manually
> kill it, does the change of processes up through amidxtaped unwind and
> amrecover resume normal processing?


Took me a while to get to do the tests.

Here an strace of amrecover at the end of the first tape:


poll([{fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=11, 
events=POLLIN}, {fd=13, events=POLLIN}, {fd=15, events=POLLIN}], 5, -1) 
= 2 ([{fd=4, revents=POLLIN}, {fd=5, revents=POLLIN}])
read(4, "\2\0\0\0\0\0\0\0", 16)         = 8
write(4, "\1\0\0\0\0\0\0\0", 8)         = 8
read(5, "\0\0@\0\0\7\241\36", 8)        = 8
read(5, 
"\204\34\313\360z\247!\324\306h\272\364\370_c\353\336$\262\224\231 
:\1\247\273\330\316\25\235c\2"..., 16384) = 16384
write(8, 
"\204\34\313\360z\247!\324\306h\272\364\370_c\353\336$\262\224\231 
:\1\247\273\330\316\25\235c\2"..., 16384) = 4096
write(4, "\1\0\0\0\0\0\0\0", 8)         = 8
write(4, "\1\0\0\0\0\0\0\0", 8)         = 8
write(4, "\1\0\0\0\0\0\0\0", 8)         = 8
poll([{fd=4, events=POLLIN}, {fd=8, events=POLLOUT}, {fd=11, 
events=POLLIN}, {fd=13, events=POLLIN}, {fd=15, events=POLLIN}], 5, -1) 
= 1 ([{fd=4, revents=POLLIN}])
read(4, "\4\0\0\0\0\0\0\0", 16)         = 8
poll([{fd=4, events=POLLIN}, {fd=8, events=POLLOUT}, {fd=11, 
events=POLLIN}, {fd=13, events=POLLIN}, {fd=15, events=POLLIN}], 5, -1) 
= 1 ([{fd=15, revents=POLLIN}])
write(4, "\1\0\0\0\0\0\0\0", 8)         = 8
read(15, "\ngzip: stdin: decompression OK, "..., 2046) = 57
write(2, "\r", 1)                       = 1
write(2, "/bin/gzip: \n", 12)           = 12
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=151148, 
si_uid=0, si_status=2, si_utime=21750, si_stime=1658} ---
write(2, "/bin/gzip: gzip: stdin: decompre"..., 67) = 67
write(4, "\1\0\0\0\0\0\0\0", 8)         = 8
poll([{fd=4, events=POLLIN}, {fd=8, events=POLLOUT}, {fd=11, 
events=POLLIN}, {fd=13, events=POLLIN}, {fd=15, events=POLLIN}], 5, -1) 
= 2 ([{fd=4, revents=POLLIN}, {fd=15, revents=POLLHUP}])
read(4, "\2\0\0\0\0\0\0\0", 16)         = 8
write(4, "\1\0\0\0\0\0\0\0", 8)         = 8
read(15, "", 1989)                      = 0
close(15)                               = 0
write(4, "\1\0\0\0\0\0\0\0", 8)         = 8
write(4, "\1\0\0\0\0\0\0\0", 8)         = 8
poll([{fd=4, events=POLLIN}, {fd=8, events=POLLOUT}, {fd=11, 
events=POLLIN}, {fd=13, events=POLLIN}], 4, -1) = 1 ([{fd=4, 
revents=POLLIN}])
read(4, "\3\0\0\0\0\0\0\0", 16)         = 8
poll([{fd=4, events=POLLIN}, {fd=8, events=POLLOUT}, {fd=11, 
events=POLLIN}, {fd=13, events=POLLIN}], 4, -1) = 2 ([{fd=11, 
revents=POLLHUP}, {fd=13, revents=POLLHUP}])
write(4, "\1\0\0\0\0\0\0\0", 8)         = 8
read(11, "", 1830)                      = 0
close(11)                               = 0
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=151150, 
si_uid=0, si_status=0, si_utime=351, si_stime=884} ---
write(4, "\1\0\0\0\0\0\0\0", 8)         = 8
write(4, "\1\0\0\0\0\0\0\0", 8)         = 8
read(13, "", 2046)                      = 0
close(13)                               = 0
write(4, "\1\0\0\0\0\0\0\0", 8)         = 8
write(4, "\1\0\0\0\0\0\0\0", 8)         = 8
write(4, "\1\0\0\0\0\0\0\0", 8)         = 8
poll([{fd=4, events=POLLIN}, {fd=8, events=POLLOUT}], 2, -1) = 1 
([{fd=4, revents=POLLIN}])



The PID 151150 was tar:

151130 pts/2    Sl+    0:02      0    94 119297 8976  0.0 amrecover abt 
-o auth=local -s localhost
  151133 pts/2    S+     0:00      0    29 19394  6552  0.0 
/usr/libexec/amanda/amandad -auth=local
  151134 pts/2    S+     0:00      0    36 20747  7864  0.0 
/usr/libexec/amanda/amindexd amandad local
  151135 pts/2    Z+     0:00      0     0     0     0  0.0 [amandad] 
<defunct>
  151138 pts/2    R+     0:00      0    29 19554  6504  0.0 
/usr/libexec/amanda/amandad -auth=local
  151139 pts/2    Sl+    0:01      0     3 233592 42820  0.2 
/usr/bin/perl /usr/libexec/amanda/amidxtaped amandad l
  151140 pts/2    Z+     0:00      0     0     0     0  0.0 [amandad] 
<defunct>
  151144 pts/4    S+     0:00      0    62  9685   940  0.0 tail -f 
amidxtaped.20220530124548.debug
  151146 pts/2    S+     0:00      0   812  5495  2984  0.0 /bin/bash 
/usr/sbin/exuvo_crypt -d
  151148 pts/2    S+     0:08      0    69  5382  1464  0.0 /bin/gzip -dc
  151150 pts/2    S+     0:00      0   385 10046  2572  0.0 tar 
--ignore-zeros --numeric-owner -xpGvf - ./etc
  151153 pts/2    R+     0:06      0   514  8301  4500  0.0 
/usr/bin/openssl enc -pbkdf2 -d -aes-256-ctr -salt -pas


-


strace openssl shows only:

# strace -p 151133
strace: Process 151133 attached
restart_syscall(<... resuming interrupted read ...>

Killing that logs in amidxtaped.xx.debug:


Mon May 30 12:55:26.730917575 2022: pid 151139: thd-0x563663659c00: 
amidxtaped: info: /usr/sbin/exuvo_crypt exited with status 143
Mon May 30 12:55:26.731039404 2022: pid 151139: thd-0x563663659c00: 
amidxtaped: unhandled XMSG_CRC <XferFilterProcess@0x563664fd4030>
Mon May 30 12:55:26.731430700 2022: pid 151139: thd-0x563663659c00: 
amidxtaped: 
/usr/lib64/perl5/vendor_perl/5.34/Amanda/Restore.pm:1913:info:4900012 
12472320 kb
Mon May 30 12:55:26.731657311 2022: pid 151139: thd-0x563663659c00: 
amidxtaped: 
/usr/lib64/perl5/vendor_perl/5.34/Amanda/Restore.pm:1941:error:4900055 
/usr/sbin/exuvo_crypt exited with status 143
Mon May 30 12:55:26.731846597 2022: pid 151139: thd-0x563663659c00: 
amidxtaped: 
/usr/lib64/perl5/vendor_perl/5.34/Amanda/Restore.pm:2174:error:4900068 
/usr/sbin/exuvo_crypt exited with status 143
Mon May 30 12:55:26.731974295 2022: pid 151139: thd-0x563663659c00: 
amidxtaped: user_message feedback: /usr/sbin/exuvo_crypt exited with 
status 143
Mon May 30 12:55:26.732036645 2022: pid 151139: thd-0x563663659c00: 
amidxtaped: CTL >> MESSAGE /usr/sbin/exuvo_crypt exited with status 143

I wait now and look what amrecover does ... amidxtaped updates the 
changer state, and exits with error code 1.

the amrecover "shell" does not yet exit, still at:

/bin/gzip: gzip: stdin: decompression OK, trailing garbage ignored

-

pstree now:

server─┬─bash───amrecover─┬─amandad─┬─amandad
                        │                  │         └─amindexd
                        │                  ├─amandad─┬─amandad
                        │                  │         └─amidxtaped
                        │                  ├─gzip
                        │                  └─tar
                        ├─bash
                        └─bash───pstree

I let it there during lunch ...

thanks, Stefan