_broker_main() crashed

[gservat]

I'm mind-blown by the speed increase we've had with mitogen for some of our playbooks (going from ~40 minutes to ~7 minutes!!). The only issue we're facing is that when the playbook ends (seemingly successful), it blurts out:

ERROR! [pid 12472] 14:59:12.774005 E mitogen: _broker_main() crashed
Traceback (most recent call last):
  File "/Users/gservat/Downloads/mitogen-stable/mitogen/core.py", line 1788, in _broker_main
    self._loop_once(max(0, deadline - time.time()))
  File "/Users/gservat/Downloads/mitogen-stable/mitogen/core.py", line 1774, in _loop_once
    for (side, func) in self.poller.poll(timeout):
  File "/Users/gservat/Downloads/mitogen-stable/mitogen/parent.py", line 560, in poll
    changelist, 32, timeout)
  File "/Users/gservat/Downloads/mitogen-stable/mitogen/core.py", line 287, in io_op
    return func(*args), False
OSError: [Errno 2] No such file or directory

Any ideas?

Python: 2.7.14

[dw]

Very curious! Can you please tell me controller machine host OS / Python version / Ansible version. Does this happen every time? Does your ansible.cfg enable any other plugins? I can't think of any poller that could report ENOENT, but apparently such a thing exists :) Please, if possible, rerun with MITOGEN_ROUTER_DEBUG=1 in your environment, and mail the /tmp/mitogen.<pid>.log file from the host machine with the lowest PID. Be careful - it writes those files on every machine targetted during the run, and they do contain sensitive data. Just the last ~50-100 lines or so is fine. Thanks for reporting this!

…

On 12 July 2018 at 06:42, Gonzalo Servat ***@***.***> wrote: I'm mind-blown by the speed increase we've had with mitogen for some of our playbooks (going from ~40 minutes to ~7 minutes!!). The only issue we're facing is that when the playbook ends (seemingly successful), it blurts out: ERROR! [pid 12472] 14:59:12.774005 E mitogen: _broker_main() crashed Traceback (most recent call last): File "/Users/gservat/Downloads/mitogen-stable/mitogen/core.py", line 1788, in _broker_main self._loop_once(max(0, deadline - time.time())) File "/Users/gservat/Downloads/mitogen-stable/mitogen/core.py", line 1774, in _loop_once for (side, func) in self.poller.poll(timeout): File "/Users/gservat/Downloads/mitogen-stable/mitogen/parent.py", line 560, in poll changelist, 32, timeout) File "/Users/gservat/Downloads/mitogen-stable/mitogen/core.py", line 287, in io_op return func(*args), False OSError: [Errno 2] No such file or directory Any ideas? — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#300>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAAJC7lu7Fe58b45uP7P8hI2oTl7OQDwks5uFuGrgaJpZM4VMPQc> .

[gservat]

Versions:

• OS: Mac OS/X 10.13.5
• Python: 2.7.14
• Ansible: 2.5.4

Seems to happen every time, yeah. If I only do one node (-l <host>) then it doesn't error out, but if I do a whole bunch of hosts then it does end with the _broker_main() crashed.
The only thing we enable in ansible.cfg is redis fact caching.

Where should I send the logs? Just attach here or mail it somewhere?

[dw]

Here is fine if they 'look innocent', otherwise dw@botanicus.net How many CPUs does your Mac have and how loaded are they? (Is it a laptop with fans spinning constantly? Monster Xserve machine with a bitcoin miner in the backgorund? etc ;). It looks possibly like "stop_transmit()" or "stop_receive()" is being called twice and there is a race, but I can't those calls are all supposed to be serialized.

…

On 12 July 2018 at 07:43, Gonzalo Servat ***@***.***> wrote: Versions: - OS: Mac OS/X 10.13.5 - Python: 2.7.14 - Ansible: 2.5.4 Seems to happen every time, yeah. The only thing we enable in ansible.cfg is redis fact caching. Where should I send the logs? Just attach here or mail it somewhere? — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#300 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAAJC9As4eFpIC_4UB08WF4WIJILUfDmks5uFvAkgaJpZM4VMPQc> .

[dw]

Aah, forgot to ask! How many targets in your run? That also influences the broker's state during shutdown. Thanks again!

…

On 12 July 2018 at 07:47, David Wilson ***@***.***> wrote: Here is fine if they 'look innocent', otherwise ***@***.*** How many CPUs does your Mac have and how loaded are they? (Is it a laptop with fans spinning constantly? Monster Xserve machine with a bitcoin miner in the backgorund? etc ;). It looks possibly like "stop_transmit()" or "stop_receive()" is being called twice and there is a race, but I can't those calls are all supposed to be serialized. On 12 July 2018 at 07:43, Gonzalo Servat ***@***.***> wrote: > Versions: > > - OS: Mac OS/X 10.13.5 > - Python: 2.7.14 > - Ansible: 2.5.4 > > Seems to happen every time, yeah. The only thing we enable in ansible.cfg > is redis fact caching. > > Where should I send the logs? Just attach here or mail it somewhere? > > — > You are receiving this because you commented. > Reply to this email directly, view it on GitHub > <#300 (comment)>, or mute > the thread > <https://github.com/notifications/unsubscribe-auth/AAAJC9As4eFpIC_4UB08WF4WIJILUfDmks5uFvAkgaJpZM4VMPQc> > . >

[gservat]

They look innocent to me (here you go).

Intel i7 CPU so 4 cores. CPUs are running hard but sadly not making any money with them :)

In terms of target size, there's 185 hosts. If I run it against a smaller batch (I tried with 23 hosts) then it seems to finish without errors.

[dw]

Please leave this with me for a day or two. I need to set up a test environment to see if those 'no route' errors are related -- that is usually a harmless race manifesting once or twice, but in this log it is appearing a ton of times. There may be a nasty shutdown ordering bug in here somewhere

[gservat]

Sure, no worries. The only other issue I've noticed (I can open a different issue if you like) is that I've been running the same playbook today against the same number of targets (180+ hosts) and I've noticed that it just stopped at one point. I had 180+ SSH processes on my workstation, and after several minutes the playbook was going nowhere. I ended up cancelling the playbook run.

[dw]

That definitely sounds like another race. Let me get an environment similar to yours and reproduce it -- I haven't tested much higher than the 80 target mark. These are usually really simple to fix once identified, but sometimes they can be difficult to tickle.

It's entirely possible "-vvv" output will reveal another source of the hang, however if it is a race, enabling "-vvv" has a very high probability of hiding it. Incredibly frustrating :) So let me try finding it first on my end.

[gservat]

Thanks very much for looking into this.

[RonnyPfannschmidt]

wouldnt still trying with -vvv enable at least looking for a indication of another reason

[gservat]

I also tried setting - serial: 25% in the playbook and ran it against the 183 hosts. The number of SSH processes went from 25% of 183 to 50% and eventually to 183 SSH processes. It's like it's not closing the old ones when they're done?

[dw]

@gservat maintaining the SSH connections is part of the design -- they're a persistent link to a fixed remote process, closing them would kill a lot of the perf benefit.

Indeed @RonnyPfannschmidt :) That wasn't very clear -- of course feel free to look at "-vvv" output, in particular any red "E" lines. They are hidden by default because the library emits so many soft errors (such as those 'no route' messages), however it's entirely possible something might stick out like a sore thumb.

[dw]

Just for @RonnyPfannschmidt 's benefit, since I know you're evaluating this presently: the 'no route' messages are exclusively relate to handle 102, aka. mitogen.core.FORWARD_LOG. There is some annoying ordering issue during disconnection where sometimes one or two log lines get dropped. It hasn't been a priority to investigate since those logs are always captured on disk anyway via MITOGEN_ROUTER_DEBUG (Router.enable_debug()), so it's mostly an inconvenience just now.

[gservat]

@dw any luck? If you had time to have a look, that is.

[dw]

Hi @gservat, I hope to have time to setup a test environment before the end of the week.. sorry, preparing to travel just now, and it's usually quite involved to find a way to tickle it :)

Sorry for the delay!