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
