Bug#1059444: LXD: cython3 autopkgtest hangs forever due to stall in copyup

[stefanor]

Hi Paul (2023.12.29_06:52:47_+)
> "The" tee? Did you happen to know which one?

tee -a -- /tmp/autopkgtest.aFkRUa/testsuite-stderr

root@autopkgtest-lxd-jvgqvo:~# ps waux
USER PID %CPU %MEMVSZ   RSS TTY  STAT START   TIME COMMAND
root   1  0.0  0.0  21680 11776 ?SNs  14:48   0:00 /sbin/init
root  42  0.0  0.0  51032 15872 ?Ss   14:48   0:00 
/usr/lib/systemd/systemd-journald
systemd+  64  0.0  0.0  19456  9216 ?SNs  14:48   0:00 
/usr/lib/systemd/systemd-networkd
systemd+  75  0.0  0.0  21200 11520 ?Ss   14:48   0:00 
/usr/lib/systemd/systemd-resolved
message+  79  0.0  0.0   8036  3840 ?Ss   14:48   0:00 
/usr/bin/dbus-daemon --system --address=systemd: --nofork --nopid
root  80  0.0  0.0  18076  7808 ?Ss   14:48   0:00 
/usr/lib/systemd/systemd-logind
root  87  0.0  0.0   2956  1920 pts/0Ss+  14:48   0:00 /sbin/agetty 
-o -p -- \u --noclear --keep-baud - 115200,38400,960
root2221  0.0  0.0   3952  2432 ?S14:49   0:00 bash -c set 
-a; [ -r /etc/environment ] && . /etc/environment 2>/
root2223  0.0  0.0   5604  3328 ?S14:49   0:00 su -s 
/bin/bash test -c set -e; exec /tmp/autopkgtest.aFkRUa/wrap
test2226  0.0  0.0  20372 10368 ?Ss   14:49   0:00 
/usr/lib/systemd/systemd --user
test2227  0.0  0.0  20832  2512 ?S14:49   0:00 (sd-pam)
test2233  0.0  0.0   2580  1664 ?Ss   14:49   0:00 /bin/sh 
/tmp/autopkgtest.aFkRUa/wrapper.sh --artifacts=/tmp/autop
test2248  0.0  0.0   2920  1536 ?S14:49   0:05 tee -a -- 
/tmp/autopkgtest.aFkRUa/testsuite-stderr
root   37211  0.0  0.0   4640  3584 pts/1Ss   15:54   0:00 bash
root   37212  0.0  0.0   8112  3968 pts/1R+   15:54   0:00 ps waux
root@autopkgtest-lxd-jvgqvo:~# strace -fp 2248
strace: Process 2248 attached
write(1, "runTest (__main__.CythonCompileT"..., 85
root@autopkgtest-lxd-jvgqvo:~# lsof -p 2248
COMMAND  PID USER   FD   TYPE DEVICE SIZE/OFF NODE NAME
tee 2248 test  cwdDIR  0,159  85825271 
/tmp/autopkgtest.aFkRUa/build.K24/src
tee 2248 test  rtdDIR  0,159  132  258 /
tee 2248 test  txtREG  0,15948112  915 /usr/bin/tee
tee 2248 test  memREG   0,26   915 /usr/bin/tee (path 
dev=0,159)
tee 2248 test  memREG   0,26  1066 
/usr/lib/locale/C.utf8/LC_CTYPE (path dev=0,159)
tee 2248 test  memREG   0,26  1073 
/usr/lib/locale/C.utf8/LC_NUMERIC (path dev=0,159)
tee 2248 test  memREG   0,26  1076 
/usr/lib/locale/C.utf8/LC_TIME (path dev=0,159)
tee 2248 test  memREG   0,26  1065 
/usr/lib/locale/C.utf8/LC_COLLATE (path dev=0,159)
tee 2248 test  memREG   0,26  1071 
/usr/lib/locale/C.utf8/LC_MONETARY (path dev=0,159)
tee 2248 test  memREG   0,26  1070 
/usr/lib/locale/C.utf8/LC_MESSAGES/SYS_LC_MESSAGES (path dev=0,159)
tee 2248 test  memREG   0,26  1074 
/usr/lib/locale/C.utf8/LC_PAPER (path dev=0,159)
tee 2248 test  memREG   0,26  1072 
/usr/lib/locale/C.utf8/LC_NAME (path dev=0,159)
tee 2248 test  memREG   0,26  1064 
/usr/lib/locale/C.utf8/LC_ADDRESS (path dev=0,159)
tee 2248 test  memREG   0,26  2433 
/usr/lib/x86_64-linux-gnu/gconv/gconv-modules.cache (path dev=0,159)
tee 2248 test  memREG   0,26  2575 
/usr/lib/x86_64-linux-gnu/libc.so.6 (path dev=0,159)
tee 2248 test  memREG   0,26  1075 
/usr/lib/locale/C.utf8/LC_TELEPHONE (path dev=0,159)
tee 2248 test  memREG   0,26  1068 
/usr/lib/locale/C.utf8/LC_MEASUREMENT (path dev=0,159)
tee 2248 test  memREG   0,26  1067 
/usr/lib/locale/C.utf8/LC_IDENTIFICATION (path dev=0,159)
tee 2248 test  memREG   0,26  2449 
/usr/lib/x86_64-linux-gnu/ld-linux-x86-64.so.2 (path dev=0,159)
tee 2248 test0r  FIFO  0,159  0t027845 /tmp/tmp.X1AEaLT6VQ/err
tee 2248 test1w  FIFO   0,14  0t0 24974400 pipe
tee 2248 test2w  FIFO   0,14  0t0 24974400 pipe
tee 2248 test3w   REG  0,159  252568727848 
/tmp/autopkgtest.aFkRUa/testsuite-stderr

The other end of that pipe is:
lxd 323739 root  297r FIFO   0,14  0t0  24974400 pipe
lxd 323739 root  298w FIFO   0,14  0t0  24974400 pipe

I assume lxd is proxying the data to and from lxc exec:

$ ps waux | grep 'lxc exec'
stefanor  125535  0.2  0.1 1540868 32312 pts/13  Sl+  10:49   0:09 
/snap/lxd/24918/bin/lxc exec autopkgtest-lxd-jvgqvo -- env -i bash -c set -a; [ 
-r /etc/environment ] && . /etc/environment 2>/dev/null || true; [ -r 
/etc/default/locale ] && . /etc/default/locale 2>/dev/null || true; [ -r 
/etc/profile ] && . /etc/profile 2>/dev/null || true; set +a;"$@"; RC=$?; [ $RC 
!= 255 ] || 

Bug#1059444: LXD: cython3 autopkgtest hangs forever due to stall in copyup

[Paul Gevers]

Hi Stefano,

On 29-12-2023 02:26, stefa...@debian.org wrote:

Hi Debian (2023.12.25_17:20:25_+)

This reproduces reliably, but I haven't got to the bottom of it. It
looks like a stalled pipeline somewhere.


Caught it again, the tee from lib/in-testbed/wrapper.sh is trying to
write to stdout, but buffer is full.


"The" tee? Did you happen to know which one?


And autopkgtest isn't reading the buffer, it's busy waiting for a write
to complete.


Which after a very quick check *hints* that we may want to add real (or 
/dev/null) stderr and stdout here:
https://salsa.debian.org/ci-team/autopkgtest/-/blob/master/lib/adt_testbed.py?ref_type=heads#L1198 
?


Paul


OpenPGP_signature.asc
Description: OpenPGP digital signature

Bug#1059444: LXD: cython3 autopkgtest hangs forever due to stall in copyup

[stefanor]

Hi Debian (2023.12.25_17:20:25_+)
> This reproduces reliably, but I haven't got to the bottom of it. It
> looks like a stalled pipeline somewhere.

Caught it again, the tee from lib/in-testbed/wrapper.sh is trying to
write to stdout, but buffer is full.

And autopkgtest isn't reading the buffer, it's busy waiting for a write
to complete.

Stefano

-- 
Stefano Rivera
  http://tumbleweed.org.za/
  +1 415 683 3272

Bug#1059444: LXD: cython3 autopkgtest hangs forever due to stall in copyup

[Stefano Rivera]

Package: autopkgtest
Version: 5.31.1
Severity: normal

This reproduces reliably, but I haven't got to the bottom of it. It
looks like a stalled pipeline somewhere.

Run autopkgtest on the current cython in unstable (3.0.6-2) with lxd,
and it'll hang forever.

Eventually failing:
pep526_variable_annotations.cpp: In function ‘PyObject* 
__pyx_pw_27pep526_variable_annotations_11test_tuple(PyObject*, PyObject* 
const*, Py_ssize_t, PyObject*)’:
pep526_variable_annotations.cpp:13880:33: note: ‘result’ declared here
13880 | __pyx_ctuple_int__and_float result;
  | ^~

autopkgtest [13:03:43]: test testsuite: ---]
Error: Failed to retrieve PID of executing child process
autopkgtest-virt-lxd [13:03:43]: copyup source failed, status 255
Error: Failed to retrieve PID of executing child process
autopkgtest [13:03:44]: ERROR: testbed failure: sent `auxverb_debug_fail', got 
`copy-failed', expected `ok...'


autopkgtest-virt-lxd is sitting in sys.stdin.readline.strip() waiting for 
instructions.

autopkgtest is waiting for lxc to finish.

Stefano

-- System Information:
Debian Release: trixie/sid
  APT prefers testing
  APT policy: (990, 'testing'), (500, 'unstable'), (1, 'experimental')
Architecture: amd64 (x86_64)

Kernel: Linux 6.5.0-5-amd64 (SMP w/16 CPU threads; PREEMPT)
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8), LANGUAGE not set
Shell: /bin/sh linked to /usr/bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled

Versions of packages autopkgtest depends on:
ii  apt-utils   2.7.6
ii  libdpkg-perl1.22.2
ii  mawk1.3.4.20231126-1
ii  procps  2:4.0.4-2
ii  python3 3.11.6-1
ii  python3-debian  0.1.49

Versions of packages autopkgtest recommends:
ii  autodep8  0.28
ii  fakeroot  1.32.2-1

Versions of packages autopkgtest suggests:
pn  docker.io
ii  fakemachine  0.0.7-2
pn  lxc  
pn  lxd  
ii  ovmf 2023.05-2
pn  ovmf-ia32
pn  podman   
ii  python3-distro-info  1.7
pn  qemu-efi-aarch64 
pn  qemu-efi-arm 
pn  qemu-system  
ii  qemu-utils   1:8.1.2+ds-1
ii  schroot  1.6.13-3+b3
ii  util-linux   2.39.3-2
ii  vmdb20.28-1
ii  zerofree 1.1.1-1

-- no debconf information