[
https://issues.apache.org/jira/browse/CASSANDRA-21859?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=18139233#comment-18139233
]
Dmitry Konstantinov commented on CASSANDRA-21859:
-------------------------------------------------
Claude have found a "deadlock" between virtualenv (pid 335 in the container)
and a background update process it started (pid 341):
h3. Hang in Cassandra-4.0-dtest-offheap #795 (jdk8, split 63)
[Console|https://ci-cassandra.apache.org/job/Cassandra-4.0-dtest-offheap/795/jdk=jdk_1.8_latest,label=cassandra-dtest,split=63/console].
At 20:54:33 UTC the split printed \{{+ virtualenv --python=python3.8 venv}}
([cassandra-dtest-pytest.sh:77|https://github.com/apache/cassandra-builds/blob/555f2ccbe342d03ee3f817ebf751253635e66f9d/build-scripts/cassandra-dtest-pytest.sh#L77]).
It printed nothing after that until the 90 min \{{noActivity}} timeout. In
split 47 of the same build, on the same agent, this step took 229 ms. 127 of
the 128 runs finished.
h4. State inside the container (cassandra28, 460b9becd9d1)
{noformat}
PID STAT WCHAN COMMAND
4060025 Sl+ futex_do_wait /usr/bin/python2.7 /usr/local/bin/virtualenv
--python=python3.8 venv
4060031 S+ anon_pipe_write /usr/bin/python2.7 -c ...
do_update(u'setuptools', '3.8', ...)
{noformat}
The container was at 0% CPU and 91 MiB memory, with no OOM and 406 GB of free
disk.
||pipe||virtualenv (pid 335 in container)||do_update child (pid 341)||
|155453669|fd 5 (r), fd 6 (w)| |
|155453670|fd 14 (r), fd 15 (w)| |
|155453671|fd 18 (r)|fd 18 (r), fd 19 (w)|
|155455539|fd 9 (r)|fd 1 (w)|
|155455540|fd 16 (r)|fd 2 (w)|
{\{~/.local/share/virtualenv/wheel/house}} holds about 35 setuptools/pip wheels
downloaded between 20:54 and 20:58, and nothing newer.
h4. Mechanism
# The image ships virtualenv 20.15.1 running on python2.7. The app-data update
log was written when the image was built (May 2025). That is older than the
14-day update period, so every container triggers a periodic update of the
embedded wheels.
# \{{FromAppDataSeeder}} resolves pip, setuptools and wheel in parallel threads
([via_app_data.py#L118-L125|https://github.com/pypa/virtualenv/blob/20.15.1/src/virtualenv/seed/embed/via_app_data/via_app_data.py#L118-L125]).
Each thread calls \{{trigger_update}}, which starts \{{do_update}} in the
background with \{{Popen(stdout=PIPE, stderr=PIPE)}} and
\{{setup_report(MAX_LEVEL)}}
([periodic_update.py#L211-L241|https://github.com/pypa/virtualenv/blob/20.15.1/src/virtualenv/seed/wheels/periodic_update.py#L211-L241]).
The parent never reads these pipes. It relies on its own exit to end them.
# Python 2.7 \{{Popen}} is not safe to call from several threads at once.
\{{pipe_cloexec()}} calls \{{os.pipe()}} and then sets \{{FD_CLOEXEC}} in a
separate \{{fcntl}} call ("This is not atomic: we would need the pipe2()
syscall for that",
[subprocess.py#L859-L867|https://github.com/python/cpython/blob/2.7/Lib/subprocess.py#L859-L867]).
\{{close_fds}} also defaults to False. The setuptools child (341) was forked
inside that window. It inherited both ends of another thread's errpipe (pipe
155453671, fds 18/19).
# That other thread is blocked in \{{os.read(errpipe_read)}}, waiting for EOF
to confirm that its child exec'd. EOF never arrives because 341 holds the write
end. This is inferred from the fds; the thread's own wchan was not captured.
The parent still holds both ends of that Popen's stdout/stderr pipes
(155453669, 155453670), and it only closes them after the errpipe read returns.
The main thread waits in \{{Thread.join}} (\{{futex_do_wait}}).
# 341 logs every download until its unread stdout/stderr pipe is full, and then
blocks in \{{anon_pipe_write}}. Deadlock: virtualenv waits for 341 to close fd
19, and 341 waits for virtualenv to read its pipe.
Every 4.0/4.1 python dtest container goes through this code path. The deadlock
needs a thread switch inside the short window between \{{pipe()}} and
\{{fcntl()}}, so it rarely fires. 5.0+ branches use the in-tree image, whose
virtualenv runs on python3. Python 3 \{{Popen}} creates pipes with
\{{pipe2(O_CLOEXEC)}} and defaults to \{{close_fds=True}}, so it is not
affected.
h4. Proposed fix
Disable the periodic update in cassandra-builds
\{{build-scripts/cassandra-dtest-pytest.sh}}:
{code:bash}
virtualenv --no-periodic-update --python=python3.8 venv
{code}
virtualenv 20.15.1 supports this flag. Setting
\{{VIRTUALENV_NO_PERIODIC_UPDATE=1}} has the same effect. It also stops every
container from downloading pip/setuptools wheels from PyPI in the background.
> "virtualenv --python=python3.8 venv" may stuck within a test container
> ----------------------------------------------------------------------
>
> Key: CASSANDRA-21859
> URL: https://issues.apache.org/jira/browse/CASSANDRA-21859
> Project: Apache Cassandra
> Issue Type: Bug
> Components: Test/dtest/python
> Reporter: Dmitry Konstantinov
> Priority: Normal
>
> https://ci-cassandra.apache.org/job/Cassandra-4.0-dtest-offheap/795/jdk=jdk_1.8_latest,label=cassandra-dtest,split=63/console
> {code}
> 20:54:33 BUILD SUCCESSFUL
> 20:54:33 Total time: 1 minute 0 seconds
> 20:54:33 + RETURN=0
> 20:54:33 + '[' 0 -eq 0 ']'
> 20:54:33 + break
> 20:54:33 + '[' 0 -ne 0 ']'
> 20:54:33 + set -e
> 20:54:33 + virtualenv --python=python3.8 venv
> 22:24:33 Build timed out (after 90 minutes). Marking the build as aborted.
> 22:24:33 Build was aborted
> 22:24:33 SSH: Current build result is [ABORTED], not going to run.
> 22:24:33 Archiving artifacts
> 22:24:34 Recording fingerprints
> 22:24:34 Recording test results
> 22:24:34 ERROR: Step ‘Publish JUnit test result report’ failed: No test
> report files were found. Configuration error?
> 22:24:34 [PostBuildScript] - [INFO] Executing post build scripts.
> 22:24:36 [63] $ /bin/sh -xe /home/jenkins/tmp/jenkins15529893812876844024.sh
> 22:24:36 + echo Cleaning processes…
> 22:24:36 Cleaning processes…
> 22:24:36 + pgrep -xa docker
> 22:24:36 31316 docker exec --user cassandra
> cassandra_ubuntu-test_test-oa_jdk21_arch-x86_64_python3-8_6_20__NoxQSf bash
> -c source ${CASSANDRA_DIR}/.build/docker/_set_java.sh 21 ;
> ${CASSANDRA_DIR}/.build/docker/_docker_init_tests.sh -a test-oa -c 6/20 ;
> exit $?
> 22:24:36 2470794 docker attach --no-stdin
> 56b52c438833fea045973c40cb06657d22e757b648fe3df920b7f9d296f9a73a
> 22:24:36 4058995 docker attach --no-stdin
> 460b9becd9d168bbaaecb61b917ecc9b4f8dc5cc489164349b05d4184ce448d8
> 22:24:36 + echo Pruning docker for 'Cassandra-Job-DSL' on cassandra-arm2…
> 22:24:36 Pruning docker for 'Cassandra-Job-DSL' on cassandra-arm2…
> 22:24:36 + cd cassandra-builds/jenkins-dsl/agent_scripts/
> 22:24:36 + bash docker_agent_cleaner.sh 12
> 22:24:36 docker system prune --force --filter "until=12h" : Total reclaimed
> space: 0B
> 22:24:38 Terminated
> 22:24:42 Error response from daemon: conflict: unable to delete
> apache/cassandra-testing-ubuntu2004-java11:latest (must be forced) -
> container 460b9becd9d1 is using its referenced image 85d655affe37
> 22:24:42 Pruning apache/cassandra-testing-ubuntu2004-java11:latest
> 22:24:42 + bash agent_report.sh
> 22:24:42 ----
> 22:24:42 Thu Nov 5 22:24:42 UTC 2026
> 22:24:42
> Cassandra-4.0-dtest-offheap/jdk=jdk_1.8_latest,label=cassandra-dtest,split=63
> 795
> 22:24:42
> 22:24:48 57G /
> 22:24:48 19G /home/jenkins/jenkins-slave/workspace
> 22:24:48 19G /home/jenkins/jenkins-slave
> 22:24:48 19G /home/jenkins
> 22:24:48 19G /home
> 22:24:48 18G /usr
> 22:24:48 13G /snap
> 22:24:48 8.0G /usr/local
> 22:24:48 7.9G /usr/local/asfpackages
> 22:24:48 7.5G /usr/local/asfpackages/java
> 22:24:48 7.0G /var
> 22:24:48 5.6G /var/lib
> 22:24:48 5.3G /home/jenkins/jenkins-slave/workspace/Cassandra-6.0
> 22:24:48 4.8G /var/lib/snapd
> 22:24:48 4.8G /usr/lib
> 22:24:48 4.7G /var/lib/snapd/snaps
> 22:24:48 3.6G
> /home/jenkins/jenkins-slave/workspace/Cassandra-devbranch-before-5-dtest/jdk
> 22:24:48 3.6G
> /home/jenkins/jenkins-slave/workspace/Cassandra-devbranch-before-5-dtest
> 22:24:48 3.1G /snap/gnome-46-2404
> 22:24:48 2.7G /snap/gnome-42-2204
> 22:24:48 2.5G /usr/share
> 22:24:48 2.3G /snap/mesa-2404
> 22:24:48 2.2G /home/jenkins/jenkins-slave/workspace/Cassandra-5.0
> 22:24:48 1.8G
> /home/jenkins/jenkins-slave/workspace/Cassandra-devbranch-before-5-dtest/jdk/jdk_11_latest/label/cassandra-dtest/split
> 22:24:48 1.8G
> /home/jenkins/jenkins-slave/workspace/Cassandra-devbranch-before-5-dtest/jdk/jdk_11_latest/label/cassandra-dtest
> 22:24:48 1.8G
> /home/jenkins/jenkins-slave/workspace/Cassandra-devbranch-before-5-dtest/jdk/jdk_11_latest/label
> 22:24:48 1.8G
> /home/jenkins/jenkins-slave/workspace/Cassandra-devbranch-before-5-dtest/jdk/jdk_11_latest
> 22:24:48 1.8G
> /home/jenkins/jenkins-slave/workspace/Cassandra-devbranch-before-5-dtest/jdk/jdk_1.8_latest/label/cassandra-dtest/split
> 22:24:48 1.8G
> /home/jenkins/jenkins-slave/workspace/Cassandra-devbranch-before-5-dtest/jdk/jdk_1.8_latest/label/cassandra-dtest
> 22:24:48 1.8G
> /home/jenkins/jenkins-slave/workspace/Cassandra-devbranch-before-5-dtest/jdk/jdk_1.8_latest/label
> 22:24:48
> 22:24:48 Filesystem Size Used Avail Use% Mounted on
> 22:24:48 /dev/root 484G 78G 406G 17% /
> 22:24:48 tmpfs 16G 0 16G 0% /dev/shm
> 22:24:48 tmpfs 6.2G 1.5M 6.2G 1% /run
> 22:24:48 tmpfs 5.0M 0 5.0M 0% /run/lock
> 22:24:48 efivarfs 128K 3.8K 120K 4% /sys/firmware/efi/efivars
> 22:24:48 /dev/nvme0n1p16 881M 183M 637M 23% /boot
> 22:24:48 /dev/nvme0n1p15 105M 6.2M 99M 6% /boot/efi
> 22:24:48 tmpfs 3.1G 16K 3.1G 1% /run/user/910
> 22:24:48
> 22:24:49 Images space usage:
> 22:24:49
> 22:24:49 REPOSITORY TAG
> IMAGE ID CREATED SIZE
> SHARED SIZE UNIQUE SIZE CONTAINERS
> 22:24:49 apache/cassandra-ubuntu-test
> dac117c7e5262cb83c9884ed451dae4e 737bfb4268d6 3 months ago 6.87GB
> 297.3MB 6.572GB 1
> 22:24:49 apache.jfrog.io/cassan-docker/apache/cassandra-debian-build
> 09a59671ba3028fcc099c9e5f8a19aaf 9003697012f0 3 months ago 4.91GB
> 195.9MB 4.714GB 0
> 22:24:49 apache.jfrog.io/cassan-docker/apache/cassandra-almalinux-build
> ee16da1d10cf8ee2f65856c0bbac7958 b82bb5045141 3 months ago 3.94GB
> 283.3MB 3.655GB 0
> 22:24:49 apache.jfrog.io/cassan-docker/apache/cassandra-ubuntu-test
> 41d5ad7e504d1f4997b161aa0644fb19 3bd076ba74a6 3 months ago 6.39GB
> 297.3MB 6.093GB 0
> 22:24:49 apache.jfrog.io/cassan-docker/apache/cassandra-bullseye-build
> 75ed6c291168e923e7f079e0bf7b9f1d 052d92918cac 3 months ago 3.85GB
> 195.9MB 3.649GB 0
> 22:24:49 apache.jfrog.io/cassan-docker/apache/cassandra-almalinux-build
> 93cb5a82f08fb13ba39f493284f45069 4591f65f4bfb 3 months ago 3.11GB
> 283.3MB 2.822GB 0
> 22:24:49 apache/cassandra-testing-ubuntu2004-java11
> latest 85d655affe37 17 months ago 4.03GB
> 32B 4.027GB 2
> 22:24:49 apache.jfrog.io/cassan-docker/alpine
> 3.19.1 c5b1261d6d3e 2 years ago 11.5MB
> 0B 11.48MB 0
> 22:24:49
> 22:24:49 Containers space usage:
> 22:24:49
> 22:24:49 CONTAINER ID IMAGE
> COMMAND LOCAL VOLUMES SIZE CREATED
> STATUS NAMES
> 22:24:49 0621e984fac4
> apache/cassandra-ubuntu-test:dac117c7e5262cb83c9884ed451dae4e "sleep 1h"
> 1 670MB 10 minutes ago Up 10 minutes
> cassandra_ubuntu-test_test-oa_jdk21_arch-x86_64_python3-8_6_20__NoxQSf
> 22:24:49 460b9becd9d1 apache/cassandra-testing-ubuntu2004-java11
> "dumb-init bash -ilc…" 1 749MB 2 hours ago
> Up 2 hours agitated_davinci
> 22:24:49 56b52c438833 apache/cassandra-testing-ubuntu2004-java11
> "dumb-init bash -ilc…" 1 812MB 25 hours ago
> Up 25 hours kind_greider
> 22:24:49
> 22:24:49 Local Volumes space usage:
> 22:24:49
> 22:24:49 VOLUME NAME
> LINKS SIZE
> 22:24:49 b66b205de5d04cffb48cdfc1cbfc860980685dc3fe1809a539946f526c71b840 0
> 10.47MB
> 22:24:49 b745f7a70ba62e1a52b7556dd6c1b3164f16f0470a5d4e10d15a56690dab34a8 0
> 13.1MB
> 22:24:49 81a864c0b5822666b6711eb57e17a1cde622b1381880c048167e911677c9dacd 0
> 12.95MB
> 22:24:49 8b98654682877aa69d809f79ca5b36460b527233c6cfd41bd01e50e442715b5c 0
> 26.29MB
> 22:24:49 25ead523a209bd959a243c56b274c18c3c7dd1a0e651741b7a5a948b2b3a34ce 0
> 10.47MB
> 22:24:49 e5ac456fa04bc06ca10fd2df6b301c9ac411fdc07ee50c9eb7b79474b31a9466 0
> 8.2MB
> 22:24:49 ac19a5214cf641f191803fd4772e824c201e7ebc29b1f93403c0276ae4298b5c 1
> 314.4kB
> 22:24:49 9c3f32ebe3567d61bcd84ab571bfb54f7f31d461a5e296605538d674dffb8df7 0
> 14.81MB
> 22:24:49 dfebee1f782d91a26202e0e5c7203b1b9f76fb17afcccdddd947553789f478aa 0
> 9.56MB
> 22:24:49 006f1a27c4ace3781db05b425f93d73b525d6340cad02ba14bc599e43fa1d956 0
> 11.76MB
> 22:24:49 6aa9611eebaa64826438ecb4b59f6cdb68cd20688d14a86958a5e3c7cda7b5a1 0
> 10.75MB
> 22:24:49 771be385f717dcdba340602b1a1e94c4af795e6d46ba01d36c1e7c7b71558185 0
> 11.05MB
> 22:24:49 b0731840e1b28424644bf6768a4c4aa2a10bebe5c6af8214f6464d819d2c6099 1
> 314.4kB
> 22:24:49 c360a43b186a8f6978140d56fbc0bec9d6262221639aa1f4432442aeab98e152 1
> 131.1kB
> 22:24:49 27c07fa441a9794a7a7e1b39ab581ffc10d3d02658ed28311b9dd3be8bf7cb47 0
> 8.482MB
> 22:24:49 8d03853efeb4d79cabd5d6ac85cfe2bb7e8ec142e7a2c8fbaf023a64f0b5e9a4 0
> 10.69MB
> 22:24:49
> 22:24:49 Build cache usage: 0B
> 22:24:49
> 22:24:49 CACHE ID CACHE TYPE SIZE CREATED LAST USED USAGE
> SHARED
> 22:24:49 + git clean -qxdff -e build/test/jmh-result.json
> 22:24:51 [WS-CLEANUP] Deleting project workspace...
> 22:24:51 [WS-CLEANUP] Deferred wipeout is used...
> 22:24:51 [WS-CLEANUP] done
> 22:24:51 Finished: ABORTED
> {code}
--
This message was sent by Atlassian Jira
(v10.3.26#10030026)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
