occasional hanging 'apt-get update' from daily cronjob since Jammy 22.04
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
apt (Ubuntu) |
Confirmed
|
Undecided
|
Unassigned |
Bug Description
Hi!
Yesterday I spotted several machines of ours where a period `apt-get update` was stalled. The `http` children were hanging in `WaitFd` (waiting for parent instructions/
We have a cronjob that runs every few hours which calls `apt-get update` and does some post-processing. We noticed that several of them had stalled at some point in time. Killing the parent (apt-get) got it unstuck, removing the locks.
Example:
```
# apt-get update
Reading package lists... Done
E: Could not get lock /var/lib/
N: Be aware that removing the lock file is not a solution and may break your system.
E: Unable to lock directory /var/lib/apt/lists/
```
Task listing:
```
root 153929 \_ /usr/sbin/CRON -f -P
root 153942 \_ /bin/sh -c [ -x /etc/zabbix/
root 153943 \_ /bin/sh /etc/zabbix/
root 154026 \_ apt-get update
_apt 154029 \_ /usr/lib/
_apt 154030 \_ /usr/lib/
_apt 154031 \_ /usr/lib/
_apt 154033 \_ /usr/lib/
```
Open (TCP) sockets. All have 1 item in the Recv-Q (probably a FIN or RST?):
```
# netstat -apn | grep -E '154026|
tcp 1 0 10.x.x.x:60868 217.x.x.x:80 CLOSE_WAIT 154030/http
tcp 1 0 10.x.x.x:40756 178.x.x.x:80 CLOSE_WAIT 154029/http
tcp 1 0 10.x.x.x:56818 185.x.x.x:80 CLOSE_WAIT 154031/http
```
All children (including gpgv) were waiting using pselect6(1, [0], NULL, NULL, NULL, NULL).
The parent (apt-get) was waiting using pselect6(10, [5 6 7 9], [], NULL, {tv_sec=0, tv_nsec=500000000}, NULL).
The http sockets in the children were at fd=3.
Parent lsof:
```
# lsof -p 154026 +E
...
apt-get 154026 root 4uW REG 8,1 0 262281 /var/lib/
apt-get 154026 root 5r FIFO 0,13 0t0 4015176 pipe 154029,http,1w
apt-get 154026 root 6r FIFO 0,13 0t0 4012448 pipe 154030,http,1w
apt-get 154026 root 7r FIFO 0,13 0t0 4015192 pipe 154031,http,1w
apt-get 154026 root 8w FIFO 0,13 0t0 4015177 pipe 154029,http,0r
apt-get 154026 root 9r FIFO 0,13 0t0 4015233 pipe 154033,gpgv,1w
apt-get 154026 root 10w FIFO 0,13 0t0 4012449 pipe 154030,http,0r
apt-get 154026 root 12w FIFO 0,13 0t0 4015193 pipe 154031,http,0r
apt-get 154026 root 14w FIFO 0,13 0t0 4015234 pipe 154033,gpgv,0r
http 154029 _apt 0r FIFO 0,13 0t0 4015177 pipe 154026,apt-get,8w
http 154029 _apt 1w FIFO 0,13 0t0 4015176 pipe 154026,apt-get,5r
http 154030 _apt 0r FIFO 0,13 0t0 4012449 pipe 154026,apt-get,10w
http 154030 _apt 1w FIFO 0,13 0t0 4012448 pipe 154026,apt-get,6r
http 154031 _apt 0r FIFO 0,13 0t0 4015193 pipe 154026,apt-get,12w
http 154031 _apt 1w FIFO 0,13 0t0 4015192 pipe 154026,apt-get,7r
gpgv 154033 _apt 0r FIFO 0,13 0t0 4015234 pipe 154026,apt-get,14w
gpgv 154033 _apt 1w FIFO 0,13 0t0 4015233 pipe 154026,apt-get,9r
```
So:
- apt-get is waiting for any data written by any of its four children (at fd 5/6/7/9)
- http and gpgv are waiting for any data written by their parent (at their respective fd 0)
Parent backtrace:
```
#0 0x00007f420116a74d in select ()
from /lib/x86_
#1 0x00007f420153fb5d in pkgAcquire:
from /lib/x86_
#2 0x00007f420161d535 in AcquireUpdate(
from /lib/x86_
#3 0x00007f420161d986 in ListUpdate(
from /lib/x86_
#4 0x00007f42016d127b in DoUpdate (CmdL=...)
at ./apt-private/
#5 0x00007f420156d73f in CommandLine:
from /lib/x86_
#6 0x00007f420169fa97 in DispatchCommandLine (CmdL=...,
Cmds=
at ./apt-private/
#7 0x0000561fc06bafbd in main (argc=2, argv=0x7ffc0e14
at ./cmdline/
```
Child backtrace:
```
#0 0x00007f58b1c9b74d in select ()
from /lib/x86_
#1 0x00007f58b237cb43 in WaitFd(int, bool, unsigned long) ()
from /lib/x86_
#2 0x00005643e37bc7b3 in BaseHttpMethod:
this=
#3 main (argv=<optimized out>) at ./methods/
```
Where this is:
```
(gdb) print *this
$1 = {<aptAuthConfMe
methodNames = std::vector of length 2, capacity 2 = {
"http", "http::
SeccompFlags = 6},
authconfs = std::vector of length 1, capacity 1 = {
std:
Server = std::unique_
get() = 0x5643e534fba0}, NextURI = "",
AllowRedirect = true, Debug = false, PipelineDepth = 10,
static FailFile = {static npos = 184467440737095
_M_dataplus = {<std::
_M_p = 0x5643e534d650 "/var/lib/
_M_
_M_local_buf = "\226", '\000' <repeats 14 times>,
_
static FailTime = 1674071760}
```
Relevant code in parent:
```
pkgAcquire:
{
...
// Run till all things have been acquired
struct timeval tv = SteadyDurationT
while (ToFetch > 0)
...
int Res;
do
{
Res = select(
}
while (Res < 0 && errno == EINTR);
```
Relevant code in child:
```
int BaseHttpMethod:
{
signal(
signal(
Server = 0;
int FailCounter = 0;
while (1)
{
// We have no commands, wait for some to arrive
if (Queue == 0)
{
if (WaitFd(
return 0;
```
Versions:
```
Ubuntu 22.04.1 LTS (Jammy Jellyfish)
apt 2.4.8
```
Preliminiary conclusion/notes:
- I don't know why it stalls, but it does. And this was not a single incident. All the stalling apt processes had stopped at a different time/day.
- Apparently there is a situation possible where there are no commands queued from the parent, and the parent isn't planning on sending any either.
- Our apt-get is invoked by a cron job which calls either `update-
- I don't know if this is 2.4.x related (on Focal we have apt 2.0.x), but it sure looks like it. I did check a few other Focal machines that lacked `update-
Let me know if there's anything I can get you. Should this be filed elsewhere? (Debian Salsa?)
Cheers,
Walter Doekes
OSSO B.V.
Patches are welcome but unfortunately there isn't much we can do otherwise, this highly depends on network specifics like latency and mtus and is never reliably reproducible.