hanging process with 100% CPU since 0.3.28

[DanielRaapDev]

Using Mitogen 0.3.29 we observed some machines having 100% CPU usage on one core. It is a python process of Mitogen parent that hangs. When our pipelines run Ansible multiple times there may exist multiple instances of such a process increasing CPU load even more.

After some debugging we found that the loop of this code is running - never ending.

while PREAMBLE_COMPRESSED_LEN-len(C)and select.select([0],[],[]):C+=os.read(0,PREAMBLE_COMPRESSED_LEN-len(C))

A strace showed the process is calling this over and over again:

read(0, "", 18277)                      = 0
pselect6(1, [0], NULL, NULL, NULL, NULL) = 1 (in [0])
read(0, "", 18277)                      = 0
pselect6(1, [0], NULL, NULL, NULL, NULL) = 1 (in [0])

This was not happening on all machines nor for each run of our Ansible pipeline.

Workaround:
After reverting back to Mitogen 0.3.27 no more problems where seen.

I think this is related to the changes in #1307. Maybe because we don't use sudo logging?!

Setup:
We use SSH with an unprivileged user and use passwordless sudo to become root. We execute Ansible in a docker container running an execution environment. So each run uses exactly the same environment.

requirements.txt:

ansible-lint==25.9.2
ansible-navigator==25.9.0
jmespath==1.0.1
lxml==6.0.2
passlib==1.7.4
sarif-tools==3.0.5
mitogen==0.3.29

[moreati]

For completeness, what is the OS and Python version on the affected machines?

[moreati]

Notes to self

pselect6(1, [0], NULL, NULL, NULL, NULL) = 1 (in [0])

pselect6() asked if a single fd (fd=0) was ready to read (such that read() would not block), return values indicate that single fd=0 is ready

read(0, "", 18277) = 0

Attempted to read upto 18277 bytes, returned (i.e. didn't block) with 0 bytes.

[DanielRaapDev]

Machines are running Ubuntu 24.04 LTS and Debian 12. Python is Python 3.12.3 or Python 3.11.2.
.

[moreati]

Brainstorming possibilities (with input from claude.ai), in roughly decending order of likelyhood by my gut feeling

1. EOF - remote end of pipe/socket that feeds fd=0 closed, or was reset
2. Race condition - something else read the data, between select() returning and calling read()
   1. another part of Mitogen
   2. something in Ansible
   3. something in PAM, ssh, or sudo (e.g. a plugin)
   4. wildcard - e.g. third-party audit, security tool, agent, etc.
3. select() false positive (I'm skeptical)

[moreati]

1. EOF - remote end of pipe/socket that feeds fd=0 closed, or was reset

If this is the case, does the parent notice? Does it do anything about it? Can it?

@DanielRaapDev

1. When you observed processes at 100% CPU were any failures or retries reported on the controller?
2. Do you have any logs or stdout from such an incident?
3. As a rough estimate how often did you observe it? E.g. 50% of playbook executions, once per 1000 executions
4. Do you have anything out of the ordinary in your authentication/authorization stack? E.g. single sign on, policy agents, endpoint managment, custom SSH config, sudo plugins, PAM plugins

[moreati]

Rather than diagnose/fix the exact cause, fixing the symptom may be more robust. E.g. have the first stage self-destruct if it hasn't reached the second stage within N seconds.

[DanielRaapDev]

1. Good that you ask. I looked in the old logs and found some error:

PLAY [name of our play] *****************
[ERROR]: [mux  38] 09:13:08.341470 E mitogen.[ssh.billing-test.buero.subshell.io]: while importing 'ansible.module_utils.json_utils'
Traceback (most recent call last):
  File "<stdin>", line 1674, in exec_module
  File "master:/usr/local/lib/python3.14/site-packages/ansible/module_utils/json_utils.py", line 27
SyntaxError: future feature annotations is not defined

But the increased CPU usage was at a later run when no such error was in the log 🤔

2. No uncommon output here. Our check runs are very minimal due symmary output only. See ansible.cfg below.

3. About 50-70% of machines were affected. But only about maybe 5-10% of the Jobs left such a process behind. So there must be a race condition be involved.

4. No fancy auth here, just SSH pub key with local key files. See ansible.cfg above for custom settings.

[defaults]
interpreter_python=auto_silent
inventory=inventory/hosts.yml
remote_user=sa_ansible
callbacks_enabled = ansible.posix.profile_tasks,ansible.posix.profile_roles
forks=32
# disable HostKeyChecking so Mitogen works on Jenkins Hosts
host_key_checking=False
gathering=smart

[privilege_escalation]
# Default to sudo:
become=True

[ssh_connection]
# Keep SSH parameters in place, so Ansible execution without Mitogen will use better SSH connection
ssh_args = -o ControlMaster=auto -o ControlPersist=600 -o PreferredAuthentications=publickey
# keeping this empty prevents too long unix_socket path error
control_path =
pipelining = True

[callback_profile_roles]
summary_only = True

[callback_profile_tasks]
summary_only = True

Btw. most Jobs only run in check mode.

[DanielRaapDev]

Rather than diagnose/fix the exact cause, fixing the symptom may be more robust. E.g. have the first stage self-destruct if it hasn't reached the second stage within N seconds.

Yeah, the synchronous call prior to #1307 did not had this issue. So something with the new way of reading the data fails where the previous detected that case! or it never happend?

[DanielRaapDev]

Thanks for your work :)

[moreati]

Yeah, the synchronous call prior to #1307 did not had this issue. So something with the new way of reading the data fails where the previous detected that case! or it never happend?

Previously it was using a single shot fp.read(N). So if the input was truncated then zlib.decompress() would have most likely have thrown an unhandled exception, thus the process(es) would have exited with a non-zerro status.

[moreati]

Please could you try 9cc0ab0, from #1349

[rda0]

I am able to somewhat reproduce this by aborting ansible-playbook runs (against ~200 hosts) with Ctrl-C.

There seem to be 2 types of "stuck" processes:

• &yellow: idle processes
• &red: busy-looping processes

Due to this issue I have some monitoring data to share, which shows some of the problematic processes:

stuck process examples

color   cputime runtime        pid       user  cmd
&red       0.1h    0.1h     279437       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))
<h2>ansible</h2><p>&yellow        0.0h      162.3h     732268     732262       root /usr/bin/python3( mitogen:user@host:3700546)
&red         153.1h      162.3h     732269     732268       root /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))
&red       0.3h    0.3h    4104182       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))</p>
<h2>stuck processes</h2><p>&red 150.6302777777778h  >10     732269     732268       root /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))</p>
&red       0.2h    0.2h      35960       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))
<h2>ansible</h2><p>&yellow        0.0h  >10     732268     732262       root /usr/bin/python3( mitogen:user@host:3700546)
&red    152.79694444444445h  >10     732269     732268       root /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))</p>
&yellow    0.0h   90.6h     348812       root  /usr/bin/python3( mitogen:user@host:712040)
&red      78.3h   90.6h     348813       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))
&red       0.1h    0.1h     663867       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))</p>
&red       0.0h    0.1h    2463164       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))</p>
&yellow    0.0h   90.6h    2248518       root  /usr/bin/python3( mitogen:user@host:711582)
&red      78.4h   90.6h    2248519       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))
&red       0.1h    0.1h     876922       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))
&yellow    0.0h 1022.4h    3222703       root  /usr/bin/python3( mitogen:user@host:2542363)
&red    1011.7h 1022.4h    3222704       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))</p>
&yellow    0.0h  162.6h    3688708       root  /usr/bin/python3( mitogen:user@host:3700546)
&red     153.4h  162.6h    3688709       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))</p>
&yellow    0.0h  666.7h    2786038       root  /usr/bin/python3( mitogen:user@host:756221)
&red     651.3h  666.7h    2786039       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))</p>
&red       0.1h    0.1h     469758       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))
&yellow    0.0h  666.7h    2038373       root  /usr/bin/python3( mitogen:user@host:757665)
&red     652.1h  666.7h    2038374       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))</p>
&yellow    0.0h   90.6h    1572053       root  /usr/bin/python3( mitogen:user@host:711582)
&red      78.3h   90.6h    1572055       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))</p>
&yellow    0.0h  666.7h     830797       root  /usr/bin/python3( mitogen:user@host:756221)
&red     652.2h  666.7h     830798       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))</p>
&red       0.2h    0.3h    3344750       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))</p>
&yellow    0.0h   38.0h    3374195       root  /usr/bin/python3( mitogen:user@host:3092216)
&red      18.8h   38.0h    3374196       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))</p>
&yellow    0.0h   38.5h    3374195       root  /usr/bin/python3( mitogen:user@host:3092216)
&red      19.3h   38.5h    3374196       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))</p>
&yellow    0.0h   38.8h    2528754       root  /usr/bin/python3( mitogen:user@host:3092216)
&red      18.8h   38.8h    2528755       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))</p>
&yellow    0.0h    1.7h    1100427       root  /usr/bin/python3( mitogen:user@host:668520)
&yellow    0.0h    1.7h    1100432       root  /usr/bin/python3( mitogen:user@host:668520)
&red       0.1h    0.1h    1114730       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))
&red       0.0h    0.0h    3374196       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))</p>
&yellow    0.0h  666.7h    1826395       root  /usr/bin/python3( mitogen:user@host:757665)
&red     632.1h  666.7h    1826396       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))
&red       0.2h    0.2h    1131234       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))
&yellow    0.0h  858.6h    3021055       root  /usr/bin/python3( mitogen:user@host:57150)
&red     845.8h  858.6h    3021056       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))</p>
&yellow    0.0h    1.2h    1100427       root  /usr/bin/python3( mitogen:user@host:668520)
&yellow    0.0h    1.2h    1100432       root  /usr/bin/python3( mitogen:user@host:668520)
&yellow    0.0h  666.7h    3954410       root  /usr/bin/python3( mitogen:user@host:756221)
&red     649.3h  666.7h    3954411       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))</p>
&yellow    0.0h  162.6h    1483873       root  /usr/bin/python3( mitogen:user@host:3700546)
&red     153.4h  162.6h    1483874       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))
&yellow    0.0h  714.6h    2180811       root  /usr/bin/python3( mitogen:user@host:7664)
&red     707.0h  714.6h    2180812       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))</p>
&yellow    0.0h   38.4h     698811       root  /usr/bin/python3( mitogen:user@host:3092216)
&red      19.3h   38.4h     698812       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))</p>
&yellow    0.0h  782.8h    1569058       root  /usr/bin/python3( mitogen:user@host:756221)
&red     769.2h  782.8h    1569059       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))</p>
&yellow    0.0h  714.6h    1081190       root  /usr/bin/python3( mitogen:user@host:7664)
&red     706.9h  714.6h    1081191       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))
&yellow    0.0h  666.7h    1012717       root  /usr/bin/python3( mitogen:user@host:756221)
&red     644.1h  666.7h    1012718       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))
&yellow    0.0h  162.6h    3905890       root  /usr/bin/python3( mitogen:user@host:3700546)
&red     153.4h  162.6h    3905891       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))</p>
&yellow    0.0h  714.6h     805821       root  /usr/bin/python3( mitogen:user@host:7664)
&red     706.7h  714.6h     805822       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))
&red       0.2h    0.2h     987350       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))
&red       0.2h    0.2h    1409297       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))</p>
&yellow    0.0h   90.6h    1874827       root  /usr/bin/python3( mitogen:user@host:711582)
&red      78.4h   90.6h    1874828       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))
&red       0.1h    0.1h    4168476       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))
&red       0.0h    0.1h    1463751       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))
&red       0.3h    0.3h    2978525       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))</p>
&yellow    0.0h  162.6h     969013       root  /usr/bin/python3( mitogen:user@host:3700546)
&red     153.4h  162.6h     969014       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))
&yellow    0.0h  666.7h     291047       root  /usr/bin/python3( mitogen:user@host:756221)
&red     646.2h  666.7h     291048       root  /usr/bin/python3 -c import sys;sys.path=[p for p in sys.path if p];import binascii,os,select,zlib;exec(zlib.decompress(binascii.a2b_base64\("xxx")))

Usually when Ctrl-C-ing it immediately aborts with ^C[ERROR]: User interrupted execution. But sometimes mitogen throws red walls of errors or exceptions and I had to hit Ctrl-C multiple times. Rarely I had to kill the ansible-playbook processes because they never aborted even after many Ctrl-Cs.

Please could you try 9cc0ab0, from #1349

I am now testing your patch and will report back later.