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.
| Julian Andres Klode (juliank) wrote | #1 |
| Walter (wdoekes) wrote | #2 |
| Walter (wdoekes) wrote | #3 |
| Walter (wdoekes) wrote | #4 |
| Walter (wdoekes) wrote | #5 |
| Walter (wdoekes) wrote | #6 |
| Launchpad Janitor (janitor) wrote | #7 |
| Changed in apt (Ubuntu): | |
| status: | New → Confirmed |
| tags: | added: jammy |
| Walter (wdoekes) wrote | #8 |
| Alexey Gavrilov (le9i0nx) wrote | #9 |
| Jay D.R. (vtsj) wrote | #10 |
| anarcat (anarcat) wrote | #11 |
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.