[Bug 1230631] New: zypper update called from ansible hangs with ZYPP_SINGLE_RPMTRANS
https://bugzilla.suse.com/show_bug.cgi?id=1230631 Bug ID: 1230631 Summary: zypper update called from ansible hangs with ZYPP_SINGLE_RPMTRANS Classification: openSUSE Product: openSUSE Distribution Version: Leap 15.6 Hardware: Other OS: Other Status: NEW Severity: Normal Priority: P5 - None Component: libzypp Assignee: zypp-maintainers@suse.de Reporter: martin.wilck@suse.com QA Contact: qa-bugs@suse.de Target Milestone: --- Found By: --- Blocker: --- A zypper update process is hanging for more than an hour. I'm using the ansible zypper module to update a system. The playbook is as simple as it gets: --- - name: Update and reboot hosts: home become: yes gather_facts: yes tasks: - name: update all packages community.general.zypper: name: '*' state: latest update_cache: yes The update task is hanging for one of the hosts. Note: ZYPP_SINGLE_RPMTRANS is set on this host. libzypp 17.34.1-150600.3.4.6 zypper 1.14.71-150600.10.2.7 Last lines in /var/log/zypp/history: 2024-09-17 10:26:53|command|root@ares|'/usr/bin/zypper' '--quiet' '--non-interactive' '--xmlout' 'update' '--type' 'package' '--auto-agree-with-licenses' '--no-recommends'| 2024-09-17 10:26:55|install|glibc-extra|2.38-150600.14.8.2|x86_64||repo-sle-update|9b79c4b8215408fadb96713529ba340b8e32e6331210a3d6bde79740df5c39ab| # 2024-09-17 10:26:55 glibc-extra installed ok 2024-09-17 10:26:55|install|glibc|2.38-150600.14.8.2|x86_64||repo-sle-update|b48788acf37cf950c73ce0f6b9ef49cabe372841045d773e0d18eac312a7b298| # 2024-09-17 10:26:55 glibc installed ok 2024-09-17 10:26:55|install|glibc-32bit|2.38-150600.14.8.2|x86_64||repo-sle-update|7ee6524dfb18e81854e1b4ccbec16f1bddc6a787d305f9028e5c13ff78a0cb63| # 2024-09-17 10:26:55 glibc-32bit installed ok 2024-09-17 10:26:55|install|libexpat1|2.4.4-150400.3.22.1|x86_64||repo-sle-update|372db388086c3f4dc9057b876272f8e6f5ecfb4ecaf80719fe2dcc1b738815e9| # 2024-09-17 10:26:55 libexpat1 installed ok 2024-09-17 10:26:55|install|libuuid1|2.39.3-150600.4.12.2|x86_64||repo-sle-update|3b3fbdcb9e25068fcf0129723f5a8636d4463a7b16b5d75ea54f7c00d3eb7878| # 2024-09-17 10:26:55 libuuid1 installed ok 2024-09-17 10:26:55|install|libopenssl3|3.1.4-150600.5.15.1|x86_64||repo-sle-update|a00145c1de9f3875b2d43d7df9488727fcd3f7821793bdddd3628d6297b9cba3| # 2024-09-17 10:26:55 libopenssl3 installed ok 2024-09-17 10:26:55|install|libblkid1|2.39.3-150600.4.12.2|x86_64||repo-sle-update|7c099998d5c5652dfd019a08e0bb3505ce13d645d33bc4fa23fa7d8b17501236| # 2024-09-17 10:26:55 libblkid1 installed ok 2024-09-17 10:26:55|install|libjpeg8|8.3.2-lp156.236.1|x86_64||graphics|474e415043a57881528e7e7494c5423cea5de82f5bd25cb0ce0685469110fac2| # 2024-09-17 10:26:55 libjpeg8 installed ok Last lines in zypper.log: 2024-09-17 10:26:53 <1> ares(22706) [zypp] TargetImpl.cc(commitInSingleTransaction):1966 TargetImpl::commit(<list>CommitPolicy( DownloadInHeaps ))586 2024-09-17 10:26:54 <1> ares(22706) [zypp::exec++] forkspawnengine.cc(start):274 Executing '/usr/lib/zypp/zypp-rpm' 2024-09-17 10:26:54 <1> ares(22706) [zypp::exec++] forkspawnengine.cc(start):427 pid 23678 launched 2024-09-17 10:26:54 <1> ares(22706) [Progress++] progressdata.cc(report):75 {#1|Executing pretrans script for: ImageMagick-config-7-SUSE-7.1.1.38-lp156.757.1.x86_64} START 2024-09-17 10:26:54 <1> ares(22706) [Progress++] progressdata.cc(report):95 {#1|Executing pretrans script for: ImageMagick-config-7-SUSE-7.1.1.38-lp156.757.1.x86_64} END 2024-09-17 10:26:54 <1> ares(22706) [Progress++] progressdata.cc(report):75 {#2|Preparing} START 2024-09-17 10:26:54 <1> ares(22706) [Progress++] progressdata.cc(report):95 {#2|Preparing} END 2024-09-17 10:26:54 <1> ares(22706) [Progress++] progressdata.cc(report):75 {#3|Installing: glibc-extra-2.38-150600.14.8.2.x86_64} START 2024-09-17 10:26:55 <1> ares(22706) [Progress++] progressdata.cc(report):95 {#3|Installing: glibc-extra-2.38-150600.14.8.2.x86_64} END 2024-09-17 10:26:55 <1> ares(22706) [zypp-core] PathInfo.cc(unlink):711 unlink /var/cache/zypp/packages/repo-sle-update/x86_64/glibc-extra-2.38-150600.14.8.2.x86_64.rpm 2024-09-17 10:26:55 <1> ares(22706) [Progress++] progressdata.cc(report):75 {#4|Installing: glibc-2.38-150600.14.8.2.x86_64} START 2024-09-17 10:26:55 <1> ares(22706) [Progress++] progressdata.cc(report):95 {#4|Installing: glibc-2.38-150600.14.8.2.x86_64} END 2024-09-17 10:26:55 <1> ares(22706) [zypp-core] PathInfo.cc(unlink):711 unlink /var/cache/zypp/packages/repo-sle-update/x86_64/glibc-2.38-150600.14.8.2.x86_64.rpm [ ... some more packages ... ] 2024-09-17 10:26:55 <1> ares(22706) [zypp-core] PathInfo.cc(unlink):711 unlink /var/cache/zypp/packages/repo-sle-update/x86_64/libblkid1-2.39.3-150600.4.12.2.x86_64.rpm 2024-09-17 10:26:55 <1> ares(22706) [Progress++] progressdata.cc(report):75 {#15|Executing postin script for: libblkid1-2.39.3-150600.4.12.2.x86_64} START 2024-09-17 10:26:55 <1> ares(22706) [Progress++] progressdata.cc(report):95 {#15|Executing postin script for: libblkid1-2.39.3-150600.4.12.2.x86_64} END 2024-09-17 10:26:55 <1> ares(22706) [Progress++] progressdata.cc(report):75 {#16|Installing: libjpeg8-8.3.2-lp156.236.1.x86_64} START 2024-09-17 10:26:55 <1> ares(22706) [Progress++] progressdata.cc(report):95 {#16|Installing: libjpeg8-8.3.2-lp156.236.1.x86_64} END 2024-09-17 10:26:55 <1> ares(22706) [zypp-core] PathInfo.cc(unlink):711 unlink /var/cache/zypp/packages/graphics/x86_64/libjpeg8-8.3.2-lp156.236.1.x86_64.rpm Local process tree: |-sshd,2493 | `-sshd,21676 | `-sshd,21714 | `-sh,22336 -c su root -c '/bin/sh -c '"'"'echo BECOME-SUCCESS-nitvvgwxsoijrshepjskqvafwibxpvha ; /usr/bin/python3 /home/martin/.ansible/tmp/ansible-tmp-1726561374.1568432-22131-10361590113718/AnsiballZ_zypper.py'"'"'' && sleep 0 | `-su,22380 root -c /bin/sh -c 'echo BECOME-SUCCESS-nitvvgwxsoijrshepjskqvafwibxpvha ; /usr/bin/python3 /home/martin/.ansible/tmp/ansible-tmp-1726561374.1568432-22131-10361590113718/AnsiballZ_zypper.py' | `-sh,22381 -c echo BECOME-SUCCESS-nitvvgwxsoijrshepjskqvafwibxpvha ; /usr/bin/python3 /home/martin/.ansible/tmp/ansible-tmp-1726561374.1568432-22131-10361590113718/AnsiballZ_zypper.py | `-python3,22382 /home/martin/.ansible/tmp/ansible-tmp-1726561374.1568432-22131-10361590113718/AnsiballZ_zypper.py | `-Zypp-main,22706 --quiet --non-interactive --xmlout update --type package --auto-agree-with-licenses --no-recommends | |-Zypp-main,23678 | | |-systemd-inhibit,23680 --what=sleep:shutdown:idle --who=zypp-rpm --mode=block --why=Zypp commit running. /usr/bin/cat | | | `-cat,23681 | | `-{Zypp-main},23679 | |-btrfs-defrag-pl,22770 /usr/lib/zypp/plugins/commit/btrfs-defrag-plugin.sh | |-snapper-zypp-pl,22776 | |-systemd-inhibit,22768 --what=sleep:shutdown:idle --who=zypp --mode=block --why=Zypp commit running. /usr/bin/cat | | `-cat,22769 | |-{Zypp-main},22712 | |-{Zypp-main},22753 | |-{Zypp-main},22754 | `-{Zypp-main},22755 strace over ID 22706 and all children shows that only 22706 is active: [pid 22706] clock_gettime(CLOCK_MONOTONIC, {tv_sec=1293344, tv_nsec=222637363}) = 0 [pid 22706] clock_gettime(CLOCK_MONOTONIC, {tv_sec=1293344, tv_nsec=222779630}) = 0 [pid 22706] poll([{fd=53, events=POLLIN|POLLERR|POLLHUP}], 1, 100) = 0 (Timeout) [pid 22706] clock_gettime(CLOCK_MONOTONIC, {tv_sec=1293344, tv_nsec=323566963}) = 0 [pid 22706] clock_gettime(CLOCK_MONOTONIC, {tv_sec=1293344, tv_nsec=323697986}) = 0 [pid 22706] poll([{fd=53, events=POLLIN|POLLERR|POLLHUP}], 1, 100) = 0 (Timeout) [pid 22706] clock_gettime(CLOCK_MONOTONIC, {tv_sec=1293344, tv_nsec=424317979}) [pid 22706] clock_gettime(CLOCK_MONOTONIC, {tv_sec=1293344, tv_nsec=424476310}) = 0 [pid 22706] poll([{fd=53, events=POLLIN|POLLERR|POLLHUP}], 1, 100) = 0 (Timeout) [pid 22706] clock_gettime(CLOCK_MONOTONIC, {tv_sec=1293344, tv_nsec=525107967}) = 0 22706 is polling on fd 53, the other end of which is owned by PID 23678: /proc/22706/fd lr-x------ 1 root root 64 Sep 17 11:05 53 -> pipe:[6204057] /proc/23678/fd l-wx------ 1 root root 64 Sep 17 11:05 13 -> pipe:[6204057] l-wx------ 1 root root 64 Sep 17 11:05 4 -> pipe:[6204057] PID 23678 is writing to a different pipe: root@ares:~ # strace -s 512 -p 23678 strace: Process 23678 attached write(3, "\n!zypp.proto.target.PackageProgress\22\4\10k\20'", 41 /proc/22706 lr-x------ 1 root root 64 Sep 17 11:05 49 -> pipe:[6204056] /proc/23678 l-wx------ 1 root root 64 Sep 17 11:05 3 -> pipe:[6204056] cat /proc/23678/stack [<0>] pipe_write+0x2c3/0x630 [<0>] vfs_write+0x2e4/0x380 [<0>] ksys_write+0x50/0xe0 [<0>] do_syscall_64+0x5b/0x80 [<0>] entry_SYSCALL_64_after_hwframe+0x7c/0xe6 Apparently PID 23678 hangs because the other end of the pipe doesn't read it. PID 22706, which is the process supposed to read the pipe, doesn't poll it's fd. -- You are receiving this mail because: You are on the CC list for the bug.
https://bugzilla.suse.com/show_bug.cgi?id=1230631 https://bugzilla.suse.com/show_bug.cgi?id=1230631#c1 Benjamin Zeller <bzeller@suse.com> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |bzeller@suse.com --- Comment #1 from Benjamin Zeller <bzeller@suse.com> --- You are running libzypp 17.34.1-150600.3.4.6 , since then the code handling the singletrans protocol has changed because we had to drop protobuf. Can you reproduce that with the most recent libzypp? -- You are receiving this mail because: You are on the CC list for the bug.
https://bugzilla.suse.com/show_bug.cgi?id=1230631 https://bugzilla.suse.com/show_bug.cgi?id=1230631#c2 --- Comment #2 from Martin Wilck <martin.wilck@suse.com> --- The btrfs-defrag process is reading from a pipe which is also connected to PID 22706 (fd 34):
cat /proc/22770/stack [<0>] pipe_read+0x2fc/0x470 [<0>] vfs_read+0x2c0/0x2e0 [<0>] ksys_read+0x50/0xe0 [<0>] do_syscall_64+0x5b/0x80 [<0>] entry_SYSCALL_64_after_hwframe+0x7c/0xe6
# ls -l /proc/22770/fd/0 lr-x------ 1 root root 64 Sep 17 11:05 0 -> pipe:[6217340] /proc/22706 l-wx------ 1 root root 64 Sep 17 11:05 34 -> pipe:[6217340] /proc/22770 lr-x------ 1 root root 64 Sep 17 11:05 0 -> pipe:[6217340] -- You are receiving this mail because: You are on the CC list for the bug.
https://bugzilla.suse.com/show_bug.cgi?id=1230631 https://bugzilla.suse.com/show_bug.cgi?id=1230631#c3 --- Comment #3 from Martin Wilck <martin.wilck@suse.com> --- (In reply to Benjamin Zeller from comment #1) I don't know if this is reproducible at all. Is the most recent libzypp installable on Leap 15.6? -- You are receiving this mail because: You are on the CC list for the bug.
https://bugzilla.suse.com/show_bug.cgi?id=1230631 https://bugzilla.suse.com/show_bug.cgi?id=1230631#c4 --- Comment #4 from Martin Wilck <martin.wilck@suse.com> --- I had to kill the zypper main process with SIGKILL. However afterwards the transaction seems to have been complete, and libzypp was at 17.35.8. Maybe the issue was caused by updating libzypp during the transaction? -- You are receiving this mail because: You are on the CC list for the bug.
https://bugzilla.suse.com/show_bug.cgi?id=1230631 https://bugzilla.suse.com/show_bug.cgi?id=1230631#c5 --- Comment #5 from Michael Andres <ma@suse.com> --- (In reply to Martin Wilck from comment #4)
I had to kill the zypper main process with SIGKILL. However afterwards the transaction seems to have been complete, and libzypp was at 17.35.8. Maybe the issue was caused by updating libzypp during the transaction?
Well, updating libzypp is quite common. Zypper(22706) and zypp-rpm(23678, which runs the rpm transaction) are both up and running, so an update of libzypp on disk should not bother them. At this point zypp-rpm is driving the transaction and zypper(libzypp) is just watching, receiving the progress and rpm output via the pipes. Killing Zypper(22706) closed the pipes. This released zypp-rpm(23678) and it continued silently. A running rpm transaction is not interrupted by killing zypper. This is expected and explains why libzypp was updated at the end. Might be a protobuf issue, but if it's reproducible with libzypp-17.35., we need to dig deeper. -- You are receiving this mail because: You are on the CC list for the bug.
participants (1)
-
bugzilla_noreply＠suse.com