qapt/dpkg hang (pipe loop?) when updating

[Dave Gilbert]

I'm on Precise alpha and do an update every few days - but I've seen this bug on older versions; just followed it
a bit more.

I click install updates in Muon, and it goes off and downloads and sets off installing - but come back to it later to find it stuck; it says Installing Updates 37% - and doen't move further.

Looking I can see a dpkg:

root 21377 10759 1 19:25 pts/19 00:00:30 /usr/bin/dpkg --status-fd 77 --unpack --auto-deconfigure /var/cache/apt/archives/python3_3.2.2-1_all.deb /var/cache/apt/archives/python3-minimal_3.2.2-1_all.deb /var/cache/apt/archives/lsb-release_4.0-0ubuntu19_amd64.deb /var/cache/apt/archives/ifupdown_0.7~beta2ubuntu3_amd64.deb /var/cache/apt/archives/ubuntu-minimal_1.257_amd64.deb ...........long list of more packages.....

strace'ing the dpkg I find it's stuck in a write to stdout:

write(1, "Preparing to replace libstdc++6-"..., 156

1 is a pts:
lrwx------ 1 root root 64 Jan 21 19:49 1 -> /dev/pts/19

so hmm - not sure how to find the other end of that, but let's look at dpkg's parent (10759):

root 10759 9734 0 19:21 pts/18 00:00:00 /usr/bin/qaptworker
It's got /dev/ptmx open, but I'm not sure how to tell if it's supposed to be reading from /dev/pts/19
strace -p on that qapt shows:

write(1, "Unpacking replacement libstrigiq"..., 1024^C <unfinished ...>

(Which is curious since that's behind the dpkg...)

lrwx------ 1 root root 64 Jan 21 19:49 1 -> /dev/pts/18

hmm, yet another pts - ok, so what about it's parent?
10759's parent is 9734:

root 9734 1 0 19:10 ? 00:00:15 /usr/bin/qaptworker

9734's strace looks like:
wait4(10759, 0x7fffde810394, WNOHANG, NULL) = 0
read(70, 0x7fffde810300, 1) = -1 EAGAIN (Resource temporarily unavailable)
nanosleep({0, 33333000}, NULL) = 0
wait4(10759, 0x7fffde810394, WNOHANG, NULL) = 0

and fd 70 is:
lr-x------ 1 root root 64 Jan 21 19:49 70 -> pipe:[4136896]

doing:

ls -l /proc/*/fd/*| grep 4136896

shows :

l-wx------ 1 root root 64 Jan 21 19:49 /proc/10759/fd/73 -> pipe:[4136896]
lr-x------ 1 root root 64 Jan 21 19:49 /proc/9734/fd/70 -> pipe:[4136896]
l-wx------ 1 root root 64 Jan 21 19:49 /proc/9734/fd/73 -> pipe:[4136896]

note that's 10759 again.
So I think we've got a loop within qapt; dpkg tries to write it's status to a pty that I *think* qapt(10759) is on the other end of; unfortunately 10759 is blocked trying to write it's stdout to a pty that I *think* qapt(9734) is on the other end of; and qapt(9734) is blocked trying to write to the pipe that only 10759 is reading from - deadlock!

I guess it only triggers sometimes depending on how full each buffer is and when each process gets back to it's poll loop.

Dave

ProblemType: Bug
DistroRelease: Ubuntu 12.04
Package: libqapt-runtime 1.2.80-0ubuntu1
ProcVersionSignature: Ubuntu 3.2.0-8.15-generic 3.2.0
Uname: Linux 3.2.0-8-generic x86_64
ApportVersion: 1.91-0ubuntu1
Architecture: amd64
CheckboxSubmission: f2d10bd9f943a85b486a282e7840a570
CheckboxSystem: 0531969bcfd4f03af7405c98dc94a948
Date: Sat Jan 21 19:59:44 2012
InstallationMedia: Ubuntu 9.10 "Karmic Koala" - Release amd64 (20091027)
ProcEnviron:
 LANGUAGE=
 PATH=(custom, user)
 LANG=en_GB.UTF-8
 SHELL=/bin/bash
SourcePackage: qapt
UpgradeStatus: Upgraded to precise on 2011-12-03 (49 days ago)

[Jonathan Thomas (echidnaman)]

The relevant code in question is located here: https://projects.kde.org/projects/extragear/sysadmin/libqapt/repository/revisions/master/entry/src/worker/workerinstallprogress.cpp

The addition of a pty is a bit recent, so it may be related to the issue. Unfortunately, I do not know as much about ptys and pipes as I should... You seem to know a lot about it, though, so if you could take a look at the code it would be much appreciated.