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.