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.