Diagnosing stuck Ansible moulti sessions #15

huyz · 2024-08-10T16:45:15Z

huyz
Aug 10, 2024

I used to have one host (out of about 8) that got stuck during one of the steps (always the same one). So I would exclude moulti for that host.
After some recent moulti updates, it now seems to work.

However, now I have two other hosts that used to work but now get stuck (always the same step for each of the hosts, although the steps are different between the hosts).

On the remote host, when I try to see what's going on by running a sort of "ansible watch":

while :; do clear; pstree -w -g 3 -s AnsiballZ_ | sed -n '/AnsiballZ/,$p'; sleep 2; done

… I see that nothing's going on at the remote host that I can detect.

Now, if I quit moulti with q t, then that seems to kickstart things up again as I see orphaned output spewing out in my terminal (and my "ansible watch" starts showing new steps again):

Traceback (most recent call last):
  File "/Users/huyz/bin/moulti", line 12, in <module>
    sys.exit(main())
             ^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/cli.py", line 167, in main
    func(args)
  File "/Users/huyz/git/moulti/src/moulti/helpers.py", line 38, in send_no_none_to_moulti_and_handle_reply
    send_to_moulti_and_handle_reply(no_none_args)
  File "/Users/huyz/git/moulti/src/moulti/helpers.py", line 33, in send_to_moulti_and_handle_reply
    reply = cast(dict[str, Any], send_to_moulti(message))
                                 ^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/protocol.py", line 248, in send_to_moulti
    with moulti_connect() as moulti_socket:
         ^^^^^^^^^^^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/protocol.py", line 137, in moulti_connect
    client_socket.connect(address)
FileNotFoundError: [Errno 2] No such file or directory
Traceback (most recent call last):
  File "/Users/huyz/bin/moulti", line 12, in <module>
    sys.exit(main())
             ^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/cli.py", line 167, in main
    func(args)
  File "/Users/huyz/git/moulti/src/moulti/helpers.py", line 38, in send_no_none_to_moulti_and_handle_reply
    send_to_moulti_and_handle_reply(no_none_args)
  File "/Users/huyz/git/moulti/src/moulti/helpers.py", line 33, in send_to_moulti_and_handle_reply
    reply = cast(dict[str, Any], send_to_moulti(message))
                                 ^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/protocol.py", line 248, in send_to_moulti
    with moulti_connect() as moulti_socket:
         ^^^^^^^^^^^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/protocol.py", line 137, in moulti_connect
    client_socket.connect(address)
FileNotFoundError: [Errno 2] No such file or directory
Traceback (most recent call last):
  File "/Users/huyz/bin/moulti", line 12, in <module>
    sys.exit(main())
             ^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/cli.py", line 167, in main
    func(args)
  File "/Users/huyz/git/moulti/src/moulti/helpers.py", line 38, in send_no_none_to_moulti_and_handle_reply
    send_to_moulti_and_handle_reply(no_none_args)
  File "/Users/huyz/git/moulti/src/moulti/helpers.py", line 33, in send_to_moulti_and_handle_reply
    reply = cast(dict[str, Any], send_to_moulti(message))
                                 ^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/protocol.py", line 248, in send_to_moulti
    with moulti_connect() as moulti_socket:
         ^^^^^^^^^^^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/protocol.py", line 137, in moulti_connect
    client_socket.connect(address)
FileNotFoundError: [Errno 2] No such file or directory
Traceback (most recent call last):
  File "/Users/huyz/bin/moulti", line 12, in <module>
    sys.exit(main())
             ^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/cli.py", line 167, in main
    func(args)
  File "/Users/huyz/git/moulti/src/moulti/helpers.py", line 38, in send_no_none_to_moulti_and_handle_reply
    send_to_moulti_and_handle_reply(no_none_args)
  File "/Users/huyz/git/moulti/src/moulti/helpers.py", line 33, in send_to_moulti_and_handle_reply
    reply = cast(dict[str, Any], send_to_moulti(message))
                                 ^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/protocol.py", line 248, in send_to_moulti
    with moulti_connect() as moulti_socket:
         ^^^^^^^^^^^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/protocol.py", line 137, in moulti_connect
    client_socket.connect(address)
FileNotFoundError: [Errno 2] No such file or directory
Traceback (most recent call last):
  File "/Users/huyz/bin/moulti", line 12, in <module>
    sys.exit(main())
             ^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/cli.py", line 167, in main
    func(args)
  File "/Users/huyz/git/moulti/src/moulti/helpers.py", line 38, in send_no_none_to_moulti_and_handle_reply
    send_to_moulti_and_handle_reply(no_none_args)
  File "/Users/huyz/git/moulti/src/moulti/helpers.py", line 33, in send_to_moulti_and_handle_reply
    reply = cast(dict[str, Any], send_to_moulti(message))
                                 ^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/protocol.py", line 248, in send_to_moulti
    with moulti_connect() as moulti_socket:
         ^^^^^^^^^^^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/protocol.py", line 137, in moulti_connect
    client_socket.connect(address)
FileNotFoundError: [Errno 2] No such file or directory
Traceback (most recent call last):                                                                                                                                                                                                                                                
  File "/Users/huyz/bin/moulti", line 12, in <module>
    sys.exit(main())
             ^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/cli.py", line 167, in main
    func(args)
  File "/Users/huyz/git/moulti/src/moulti/helpers.py", line 38, in send_no_none_to_moulti_and_handle_reply
    send_to_moulti_and_handle_reply(no_none_args)
  File "/Users/huyz/git/moulti/src/moulti/helpers.py", line 33, in send_to_moulti_and_handle_reply
    reply = cast(dict[str, Any], send_to_moulti(message))
                                 ^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/protocol.py", line 248, in send_to_moulti
    with moulti_connect() as moulti_socket:
         ^^^^^^^^^^^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/protocol.py", line 137, in moulti_connect
    client_socket.connect(address)
FileNotFoundError: [Errno 2] No such file or directory
Traceback (most recent call last):
  File "/Users/huyz/bin/moulti", line 12, in <module>
    sys.exit(main())
             ^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/cli.py", line 167, in main
    func(args)
  File "/Users/huyz/git/moulti/src/moulti/helpers.py", line 38, in send_no_none_to_moulti_and_handle_reply
    send_to_moulti_and_handle_reply(no_none_args)
  File "/Users/huyz/git/moulti/src/moulti/helpers.py", line 33, in send_to_moulti_and_handle_reply
    reply = cast(dict[str, Any], send_to_moulti(message))
                                 ^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/protocol.py", line 248, in send_to_moulti
    with moulti_connect() as moulti_socket:
         ^^^^^^^^^^^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/protocol.py", line 137, in moulti_connect
    client_socket.connect(address)
FileNotFoundError: [Errno 2] No such file or directory
    ~.ans    master *1 !8 ··········································································································································································································· ✔  21m 53s   ▼  system    
❯ Traceback (most recent call last):
  File "/Users/huyz/bin/moulti", line 12, in <module>
    sys.exit(main())
             ^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/cli.py", line 167, in main
    func(args)
  File "/Users/huyz/git/moulti/src/moulti/helpers.py", line 38, in send_no_none_to_moulti_and_handle_reply
    send_to_moulti_and_handle_reply(no_none_args)
  File "/Users/huyz/git/moulti/src/moulti/helpers.py", line 33, in send_to_moulti_and_handle_reply
    reply = cast(dict[str, Any], send_to_moulti(message))
                                 ^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/protocol.py", line 248, in send_to_moulti
    with moulti_connect() as moulti_socket:
         ^^^^^^^^^^^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/protocol.py", line 137, in moulti_connect
    client_socket.connect(address)
FileNotFoundError: [Errno 2] No such file or directory
Traceback (most recent call last):
  File "/Users/huyz/bin/moulti", line 12, in <module>
    sys.exit(main())
             ^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/cli.py", line 167, in main
    func(args)
  File "/Users/huyz/git/moulti/src/moulti/helpers.py", line 38, in send_no_none_to_moulti_and_handle_reply
    send_to_moulti_and_handle_reply(no_none_args)
  File "/Users/huyz/git/moulti/src/moulti/helpers.py", line 33, in send_to_moulti_and_handle_reply
    reply = cast(dict[str, Any], send_to_moulti(message))
                                 ^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/protocol.py", line 248, in send_to_moulti
    with moulti_connect() as moulti_socket:
         ^^^^^^^^^^^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/protocol.py", line 137, in moulti_connect
    client_socket.connect(address)
FileNotFoundError: [Errno 2] No such file or directory
Traceback (most recent call last):
  File "/Users/huyz/bin/moulti", line 12, in <module>
    sys.exit(main())
             ^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/cli.py", line 167, in main
    func(args)
  File "/Users/huyz/git/moulti/src/moulti/helpers.py", line 38, in send_no_none_to_moulti_and_handle_reply
    send_to_moulti_and_handle_reply(no_none_args)
  File "/Users/huyz/git/moulti/src/moulti/helpers.py", line 33, in send_to_moulti_and_handle_reply
    reply = cast(dict[str, Any], send_to_moulti(message))
                                 ^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/protocol.py", line 248, in send_to_moulti
    with moulti_connect() as moulti_socket:
         ^^^^^^^^^^^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/protocol.py", line 137, in moulti_connect
    client_socket.connect(address)
FileNotFoundError: [Errno 2] No such file or directory
Traceback (most recent call last):
  File "/Users/huyz/bin/moulti", line 12, in <module>
    sys.exit(main())
             ^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/cli.py", line 167, in main
    func(args)
  File "/Users/huyz/git/moulti/src/moulti/helpers.py", line 38, in send_no_none_to_moulti_and_handle_reply
    send_to_moulti_and_handle_reply(no_none_args)
  File "/Users/huyz/git/moulti/src/moulti/helpers.py", line 33, in send_to_moulti_and_handle_reply
    reply = cast(dict[str, Any], send_to_moulti(message))
                                 ^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/protocol.py", line 248, in send_to_moulti
    with moulti_connect() as moulti_socket:
         ^^^^^^^^^^^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/protocol.py", line 137, in moulti_connect
    client_socket.connect(address)
FileNotFoundError: [Errno 2] No such file or directory
Traceback (most recent call last):
  File "/Users/huyz/bin/moulti", line 12, in <module>
    sys.exit(main())
             ^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/cli.py", line 167, in main
    func(args)
  File "/Users/huyz/git/moulti/src/moulti/helpers.py", line 38, in send_no_none_to_moulti_and_handle_reply
    send_to_moulti_and_handle_reply(no_none_args)
  File "/Users/huyz/git/moulti/src/moulti/helpers.py", line 33, in send_to_moulti_and_handle_reply
    reply = cast(dict[str, Any], send_to_moulti(message))
                                 ^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/protocol.py", line 248, in send_to_moulti
    with moulti_connect() as moulti_socket:
         ^^^^^^^^^^^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/protocol.py", line 137, in moulti_connect
    client_socket.connect(address)
FileNotFoundError: [Errno 2] No such file or directory
Traceback (most recent call last):
  File "/Users/huyz/bin/moulti", line 12, in <module>
    sys.exit(main())
             ^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/cli.py", line 167, in main
    func(args)
  File "/Users/huyz/git/moulti/src/moulti/helpers.py", line 38, in send_no_none_to_moulti_and_handle_reply
    send_to_moulti_and_handle_reply(no_none_args)
  File "/Users/huyz/git/moulti/src/moulti/helpers.py", line 33, in send_to_moulti_and_handle_reply
    reply = cast(dict[str, Any], send_to_moulti(message))
                                 ^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/protocol.py", line 248, in send_to_moulti
    with moulti_connect() as moulti_socket:
         ^^^^^^^^^^^^^^^^
  File "/Users/huyz/git/moulti/src/moulti/protocol.py", line 137, in moulti_connect
    client_socket.connect(address)
FileNotFoundError: [Errno 2] No such file or directory
object address  : 0x1200fa140
object refcount : 2
object type     : 0x102ff2fb0
object type name: ValueError
object repr     : ValueError('write to closed file')
lost sys.stderr

If I run the Ansible playbooks without moulti, I have no such freezing problem.

I'm trying to diagnose and collect more info about what could be going wrong. For each susceptible Ansible playbook, looking at the Ansible step that looks responsible for locking things up, I can't discern anything special about the step. They're very ordinary steps, e.g. am ansible.builtin.copy or

Any tips on how else I could diagnose this? Maybe run moulti in debugging mode?

Answered by xavierog

Feb 3, 2025

Diagnosis

What happens?

Expected behaviour

When Moulti's Ansible plugin needs to add lines to an existing Moulti step, it runs a moulti pass command and pipes those lines to the standard input of the resulting child process.
When a new step is to be created, the plugin closes this pipe and waits until the child process exits.
On the other end, the Moulti instance receives EOF and responds to the initial "pass" message by sending a simple reply (usually "done: True, error: None").
Upon reception of this reply, moulti pass exits, ending the plugin's wait.
The plugin can then resume its activity.

Encountered behaviour

Same as the expected behaviour except that, at some point, the Moulti inst…

View full answer

xavierog · 2024-08-10T18:02:14Z

xavierog
Aug 10, 2024
Maintainer

Definitely sounds like a bug in Moulti. I may have overlooked something re: Ansible parallelism. It may also be an issue with the way Moulti reads data from moulti pass, but that is not my hunch so far.

Something that does not hurt and that you can try is setting export MOULTI_PASS_CONCURRENCY=400 -- this is 20 times the default value and essentially means "Moulti, do not skimp on threads".

Overall, that looks like a reproducible issue. Ideally, you should be able to turn your playbook into a minimal reproducible example that you could share without revealing anything relevant. I would also need your ansible-playbook command line since it may affect the way Ansible behaves.

Beyond that, what to look at to diagnose what happens:

list of processes and threads involved, e.g. pstree -napu $(pgrep -f 'moulti run') -- since moulti run launches ansible-playbook, this should show everything relevant.
the output of the Moulti console (keybinding: n) can be copied (keybinding: c), anonymized (look up 'answer': otherwise you risk leaking credentials) and shared.
Overall, inspecting the situation when things get stuck is more relevant than inspecting what happens when you quit Moulti because things got stuck.
Advanced inspection involves dtruss to determine what the various processes are doing and which ones are stuck on a read() syscall.

9 replies

xavierog Aug 31, 2024
Maintainer

Additionally, which exact version of these do you use?

macOS X
Python
Ansible

huyz Sep 1, 2024
Author

I hadn't enabled MOULTI_RUN_OUTPUT=harvest but I just did and re-ran. I don't see any extra input.

I'm running:

macOS 14.6.1 23G93 (Sonoma) MacBookPro18,2 (Apple M1 Max, arm64)
Python 3.11.9
Ansible 2.17.2

❯ ansible-playbook --version
ansible-playbook [core 2.17.2]
  config file = /Users/huyz/.ansible.cfg
  configured module search path = ['/Users/huyz/.ansible/plugins/modules', '/opt/local/share/ansible/plugins/modules']
  ansible python module location = /opt/local/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/site-packages/ansible
  ansible collection location = /Users/huyz/.ansible/collections:/opt/local/share/ansible/collections
  executable location = /Users/huyz/bin/ansible-playbook
  python version = 3.11.9 (main, Apr  3 2024, 23:19:16) [Clang 15.0.0 (clang-1500.1.0.2.5)] (/opt/local/Library/Frameworks/Python.framework/Versions/3.11/bin/python3.11)
  jinja version = 3.1.4
  libyaml = True

       └─┬= 69514 huy /opt/local/Library/Frameworks/Python.framework/Versions/3.11/Resources/Python.app/Contents/MacOS/Python /opt/local/Library/Frameworks/Python.framework/Versions/3.11/bin/moulti run -- ansible-playbook site.book.yml -vvv
         └─┬─ 69523 huy /opt/local/Library/Frameworks/Python.framework/Versions/3.11/Resources/Python.app/Contents/MacOS/Python /Users/huyz/bin/ansible-playbook site.book.yml -vvv
           ├─── 69525 huy /opt/local/Library/Frameworks/Python.framework/Versions/3.11/Resources/Python.app/Contents/MacOS/Python -c from multiprocessing.resource_tracker import main;main(10)
           ├─── 73306 huy /opt/local/Library/Frameworks/Python.framework/Versions/3.11/Resources/Python.app/Contents/MacOS/Python /opt/local/Library/Frameworks/Python.framework/Versions/3.11/bin/moulti pass ansible_69523_47
           └─── 73308 huy /opt/local/Library/Frameworks/Python.framework/Versions/3.11/Resources/Python.app/Contents/MacOS/Python /Users/huyz/bin/ansible-playbook site.book.yml -vvv

xavierog Jan 26, 2025
Maintainer

macOS 14.6.1 23G93 (Sonoma) MacBookPro18,2 (Apple M1 Max, arm64)

Ok, I got macOS 14.7.2 23H311 (Sonoma) -- close enough.

Python 3.11.9

Ok, I got 3.11.9 (v3.11.9:de54cf5be3, Apr 2 2024, 07:12:50) [Clang 13.0.0 (clang-1300.0.29.30)] -- close enough too.

Ansible 2.17.2

Ok, I got ansible-playbook [core 2.17.2]... but that is just the core version.
Can you also tell me the Ansible community version? ansible-community --version

xavierog Jan 28, 2025
Maintainer

@huyz I spent some time playing with Moulti on Sonoma+Python 3.11; I quickly spotted multiple issues, some of which could be the root cause of the behaviour you described. Those issues are theoretically fixed in Moulti v1.30.1. Could you please upgrade to this new version and tell me whether you still encounter troubles?

huyz Jan 29, 2025
Author

@xavierog Still the same unfortunately.

xavierog · 2024-08-11T17:57:28Z

xavierog
Aug 11, 2024
Maintainer

Not that simple to reproduce: I gave it a first try using 10 VMs and dummy tasks (like copying a small text file or sleeping a random number of seconds): everything went smoothly.
Any suggestion to make this test closer to your playbook?

moulti run -- ansible-playbook test-multi-machines.yaml

- name: 'Moulti + Ansible + multiple hosts'
  user: root
  hosts:
  - moulti0
  - moulti1
  - moulti2
  - moulti3
  - moulti4
  - moulti5
  - moulti6
  - moulti7
  - moulti8
  - moulti9
  gather_facts: false
  tasks:
  - ansible.builtin.copy: src=/etc/passwd dest=/home/vagrant/passwd0
  - ansible.builtin.shell: sleep $(((RANDOM%10)))
    args:
      executable: /bin/bash
  - ansible.builtin.copy: src=/etc/passwd dest=/home/vagrant/passwd1
  - ansible.builtin.shell: sleep $(((RANDOM%10)))
    args:
      executable: /bin/bash
  - ansible.builtin.copy: src=/etc/passwd dest=/home/vagrant/passwd2
  - ansible.builtin.shell: sleep $(((RANDOM%10)))
    args:
      executable: /bin/bash
  - ansible.builtin.copy: src=/etc/passwd dest=/home/vagrant/passwd3
  - ansible.builtin.shell: sleep $(((RANDOM%10)))
    args:
      executable: /bin/bash
  - ansible.builtin.copy: src=/etc/passwd dest=/home/vagrant/passwd4
  - ansible.builtin.shell: sleep $(((RANDOM%10)))
    args:
      executable: /bin/bash
  - ansible.builtin.copy: src=/etc/passwd dest=/home/vagrant/passwd5
  - ansible.builtin.shell: sleep $(((RANDOM%10)))
    args:
      executable: /bin/bash
  - ansible.builtin.copy: src=/etc/passwd dest=/home/vagrant/passwd6
  - ansible.builtin.shell: sleep $(((RANDOM%10)))
    args:
      executable: /bin/bash
  - ansible.builtin.copy: src=/etc/passwd dest=/home/vagrant/passwd7
  - ansible.builtin.shell: sleep $(((RANDOM%10)))
    args:
      executable: /bin/bash
  - ansible.builtin.copy: src=/etc/passwd dest=/home/vagrant/passwd8
  - ansible.builtin.shell: sleep $(((RANDOM%10)))
    args:
      executable: /bin/bash
  - ansible.builtin.copy: src=/etc/passwd dest=/home/vagrant/passwd9
  - ansible.builtin.shell: sleep $(((RANDOM%10)))
    args:
      executable: /bin/bash
  - ansible.builtin.copy: src=/etc/passwd dest=/home/vagrant/passwda
  - ansible.builtin.shell: sleep $(((RANDOM%10)))
    args:
      executable: /bin/bash
  - ansible.builtin.copy: src=/etc/passwd dest=/home/vagrant/passwdb
  - ansible.builtin.shell: sleep $(((RANDOM%10)))
    args:
      executable: /bin/bash
  - ansible.builtin.copy: src=/etc/passwd dest=/home/vagrant/passwdc
  - ansible.builtin.shell: sleep $(((RANDOM%10)))
    args:
      executable: /bin/bash
  - ansible.builtin.copy: src=/etc/passwd dest=/home/vagrant/passwdd
  - ansible.builtin.shell: sleep $(((RANDOM%10)))
    args:
      executable: /bin/bash
  - ansible.builtin.copy: src=/etc/passwd dest=/home/vagrant/passwde
  - ansible.builtin.shell: sleep $(((RANDOM%10)))
    args:
      executable: /bin/bash
  - ansible.builtin.copy: src=/etc/passwd dest=/home/vagrant/passwdf
  - ansible.builtin.shell: sleep $(((RANDOM%10)))
    args:
      executable: /bin/bash
  - ansible.builtin.copy: src=/etc/passwd dest=/home/vagrant/passwdg
  - ansible.builtin.shell: sleep $(((RANDOM%10)))
    args:
      executable: /bin/bash
  - ansible.builtin.copy: src=/etc/passwd dest=/home/vagrant/passwdh
  - ansible.builtin.shell: sleep $(((RANDOM%10)))
    args:
      executable: /bin/bash
  - ansible.builtin.copy: src=/etc/passwd dest=/home/vagrant/passwdi
  - ansible.builtin.shell: sleep $(((RANDOM%10)))
    args:
      executable: /bin/bash
  - ansible.builtin.copy: src=/etc/passwd dest=/home/vagrant/passwdj
  - ansible.builtin.shell: sleep $(((RANDOM%10)))
    args:
      executable: /bin/bash
  - ansible.builtin.copy: src=/etc/passwd dest=/home/vagrant/passwdk
  - ansible.builtin.shell: sleep $(((RANDOM%10)))
    args:
      executable: /bin/bash
  - ansible.builtin.copy: src=/etc/passwd dest=/home/vagrant/passwdl
  - ansible.builtin.shell: sleep $(((RANDOM%10)))
    args:
      executable: /bin/bash
  - ansible.builtin.copy: src=/etc/passwd dest=/home/vagrant/passwdm

5 replies

huyz Aug 13, 2024
Author

Wow, thanks for trying to diagnose it even with the little information I gave you. I will try to give you more info. Just a bit busy these days. Please bear with me :)

xavierog Aug 27, 2024
Maintainer

Could there be a link between this discussion and issue #16? For instance, Ansible would ask a password through the tty, but the prompt would be erased by a screen refresh, leaving you with the feeling that the whole thing got stuck. A possible side-effect is that you would need to press q and t twice before Moulti detects those keypresses.

huyz Aug 31, 2024
Author

Ok let me take a look today and see if I can diagnose and gather more details. Thanks for your patience!

huyz Aug 31, 2024
Author

It doesn't look like a password prompt is related based on my tests

xavierog Aug 31, 2024
Maintainer

Fair enough. If you find some time for this matter, try to turn your playbook into a MRE.

xavierog · 2025-01-09T21:46:08Z

xavierog
Jan 9, 2025
Maintainer

@huyz
Do you still experience this issue?

On my side, I recently stumbled upon a stuck Moulti instance.
Strictly speaking, the situation is not the one you described: I was using moulti diff (which, under the hood, uses pipelining to communicate with a Moulti instance) through moulti-git-review, whereas the Ansible plugin spawns independent moulti step and moulti pass processes.
However, the deadlock I observed incentivized me to improve the server part of Moulti, and I wonder whether these improvements affect this issue. They are currently available in the devel branch:
pipx install --force git+https://github.com/xavierog/moulti.git@devel

16 replies

huyz Jan 30, 2025
Author

The Moulti console doesn't say much. It just ends with regular output at the freeze

[…]
2025-01-30T06:15:23.610 /Users/huyz/Library/Caches/moulti/moulti-client-huyz-93759.socket:fd11: accept: accepted new connection
2025-01-30T06:15:23.617 /Users/huyz/Library/Caches/moulti/moulti-client-huyz-93759.socket:fd11: => message={'msgid': '46f05575-a483-47d0-a422-4c3ded729183', 'id': 'ansible_77409_176', 'title': 'TASK: Delete temporary files', 'classes': 'ansible ansible_task', 'scroll_on_activity': -1, 'collapsed': True, 'top_text': '', 'bottom_text': ' ', 'text': '', 'auto_scroll': True, 'min_height': 1, 'max_height': 25, 'command': 'step', 'action': 'add'} file_descriptors=[]
2025-01-30T06:15:23.634 /Users/huyz/Library/Caches/moulti/moulti-client-huyz-93759.socket:fd11: <= message={'msgid': '46f05575-a483-47d0-a422-4c3ded729183', 'done': True, 'error': None}
2025-01-30T06:15:23.637 /Users/huyz/Library/Caches/moulti/moulti-client-huyz-93759.socket:fd11: read: closed connection; cause: connection closed by peer
2025-01-30T06:15:23.708 /Users/huyz/Library/Caches/moulti/moulti-client-huyz-93760.socket:fd11: accept: accepted new connection
2025-01-30T06:15:23.893 /Users/huyz/Library/Caches/moulti/moulti-client-huyz-93760.socket:fd11: => message={'msgid': '42f4922b-2efc-44c1-91b2-8fd2e1d24ffc', 'id': 'ansible_77409_176', 'top_text': 'Started 2025-01-30 06:15:23.644', 'command': 'step', 'action': 'update'} file_descriptors=[]
2025-01-30T06:15:23.934 /Users/huyz/Library/Caches/moulti/moulti-client-huyz-93760.socket:fd11: <= message={'msgid': '42f4922b-2efc-44c1-91b2-8fd2e1d24ffc', 'done': True, 'error': None}
2025-01-30T06:15:23.935 /Users/huyz/Library/Caches/moulti/moulti-client-huyz-93760.socket:fd11: read: closed connection; cause: connection closed by peer
2025-01-30T06:15:24.013 /Users/huyz/Library/Caches/moulti/moulti-client-huyz-93812.socket:fd11: accept: accepted new connection
2025-01-30T06:15:24.013 /Users/huyz/Library/Caches/moulti/moulti-client-huyz-93814.socket:fd20: accept: accepted new connection
2025-01-30T06:15:24.025 /Users/huyz/Library/Caches/moulti/moulti-client-huyz-93812.socket:fd11: => message={'msgid': 'c5958d30-13c2-4212-ab4f-0da66584a4c2', 'command': 'step', 'action': 'clear', 'id': 'ansible_77409_176'} file_descriptors=[]
2025-01-30T06:15:24.035 /Users/huyz/Library/Caches/moulti/moulti-client-huyz-93812.socket:fd11: <= message={'msgid': 'c5958d30-13c2-4212-ab4f-0da66584a4c2', 'done': True, 'error': None}
2025-01-30T06:15:24.036 /Users/huyz/Library/Caches/moulti/moulti-client-huyz-93814.socket:fd20: => message={'msgid': 'ef664668-4c83-40a3-b294-410f06279caf', 'id': 'ansible_77409_176', 'classes': 'ansible ansible_task success', 'command': 'step', 'action': 'update'} file_descriptors=[]
2025-01-30T06:15:24.038 /Users/huyz/Library/Caches/moulti/moulti-client-huyz-93814.socket:fd20: <= message={'msgid': 'ef664668-4c83-40a3-b294-410f06279caf', 'done': True, 'error': None}
2025-01-30T06:15:24.039 /Users/huyz/Library/Caches/moulti/moulti-client-huyz-93812.socket:fd11: => message={'msgid': '03081046-f34a-415b-b512-abe2f282a061', 'command': 'pass', 'id': 'ansible_77409_176', 'read_size': 8192} file_descriptors=[21]
2025-01-30T06:15:24.040 /Users/huyz/Library/Caches/moulti/moulti-client-huyz-93814.socket:fd20: read: closed connection; cause: connection closed by peer

It's always been like this.

xavierog Jan 30, 2025
Maintainer

It does tell us a few things:

the blocking happens during a moulti pass (although that was already my assumption)
the file descriptor (here, file descriptor number 21) is received just fine

At this stage, either Ansible+Moulti's Ansible plugin is failing to write to the pipe, or the Moulti instance is failing to read from the file descriptor. I remain interested in the complete, unabridged output as it may reveal some more things (e.g. the evolution of the file descriptor number can be interesting; plus, any error happening in the middle may or may not have consequences).

By the way, this also means that, even if we fail to understand and fix that bug, we could work around the problem by replacing moulti pass with a bunch of moulti step append (inelegant but presumably more reliable).

xavierog Feb 3, 2025
Maintainer

Not shown here: close cooperation outside Github to diagnose the exact cause of this issue.

xavierog Feb 3, 2025
Maintainer

Diagnosis

What happens?

Expected behaviour

When Moulti's Ansible plugin needs to add lines to an existing Moulti step, it runs a moulti pass command and pipes those lines to the standard input of the resulting child process.
When a new step is to be created, the plugin closes this pipe and waits until the child process exits.
On the other end, the Moulti instance receives EOF and responds to the initial "pass" message by sending a simple reply (usually "done: True, error: None").
Upon reception of this reply, moulti pass exits, ending the plugin's wait.
The plugin can then resume its activity.

Encountered behaviour

Same as the expected behaviour except that, at some point, the Moulti instance does not receive EOF after the pipe was closed.

Why does this happen?

Ansible is liable to fork processes.
Some of these forks quickly become ssh or sftp processes: this happens through fork() and exec(), a mechanism that does not leak file descriptors because, by default, Python file descriptors are close-on-exec (O_CLOEXEC, FD_CLOEXEC, etc.).
Other forks are used by Ansible itself to run various things. These child processes inherit all file descriptors from their parent (Python does not use close-on-fork CLOFORK at all), including the pipe described in the previous section, which is now referenced in both parent and child processes.
This extra reference in the child process does not prevent the parent from closing its file descriptor but it prevents the kernel from sending EOF to the Moulti instance, and this until the child process exits.
This results in what has been described here as a "stuck Ansible Moulti session".

Solutions

Workaround

A possible workaround is not to use moulti pass. This was implemented in 9ac2144 and can be enabled by setting the environment variable MOULTI_ANSIBLE_WRITE_MODE=append.

Fix

A proper fix is to detect forks and close the inherited file descriptor immediately. This was implemented in 13a0ebe and released as part of v1.31.0 on 2025-02-03.

Answer selected by huyz

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Diagnosing stuck Ansible moulti sessions #15

{{title}}

Replies: 3 comments 30 replies

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{title}}

{{title}}

Select a reply

Diagnosing stuck Ansible moulti sessions #15

huyz Aug 10, 2024

Diagnosis

What happens?

Expected behaviour

Encountered behaviour

Replies: 3 comments · 30 replies

xavierog Aug 10, 2024 Maintainer

xavierog Aug 31, 2024 Maintainer

huyz Sep 1, 2024 Author

xavierog Jan 26, 2025 Maintainer

xavierog Jan 28, 2025 Maintainer

huyz Jan 29, 2025 Author

xavierog Aug 11, 2024 Maintainer

huyz Aug 13, 2024 Author

xavierog Aug 27, 2024 Maintainer

huyz Aug 31, 2024 Author

huyz Aug 31, 2024 Author

xavierog Aug 31, 2024 Maintainer

xavierog Jan 9, 2025 Maintainer

huyz Jan 30, 2025 Author

xavierog Jan 30, 2025 Maintainer

xavierog Feb 3, 2025 Maintainer

xavierog Feb 3, 2025 Maintainer

Diagnosis

What happens?

Expected behaviour

Encountered behaviour

Why does this happen?

Solutions

Workaround

Fix

huyz
Aug 10, 2024

Replies: 3 comments 30 replies

xavierog
Aug 10, 2024
Maintainer

xavierog Aug 31, 2024
Maintainer

huyz Sep 1, 2024
Author

xavierog Jan 26, 2025
Maintainer

xavierog Jan 28, 2025
Maintainer

huyz Jan 29, 2025
Author

xavierog
Aug 11, 2024
Maintainer

huyz Aug 13, 2024
Author

xavierog Aug 27, 2024
Maintainer

huyz Aug 31, 2024
Author

huyz Aug 31, 2024
Author

xavierog Aug 31, 2024
Maintainer

xavierog
Jan 9, 2025
Maintainer

huyz Jan 30, 2025
Author

xavierog Jan 30, 2025
Maintainer

xavierog Feb 3, 2025
Maintainer

xavierog Feb 3, 2025
Maintainer