ERROR! [pid 28651] 18:23:43.174203 E mitogen.ctx.local.28788: mitogen: <IoLogger stderr> crashed

[dewthefifth]

I noticed today, after making some modifications to my playbook to include the XML module instead of lineinfile, that after the playbook has finished its play recap it was printing error messages out of mitogen.

The attached message is printed when running the playbook with -vvvv, and is printed AFTER my prompt has already returned. In fact, the zamrok@laptop -> ~/rigors/ansible-scripts/ansible-install: portion is my prompt.

Environment:
Ansible Host: Windows Subsystem Linux
Ansible Target: Centos 7 running on Virtualbox

zamrok@HBKSNH2 -> /etc: pip freeze
ansible==2.5.2
asn1crypto==0.23.0
bcrypt==3.1.4
cffi==1.11.2
cryptography==2.1.4
ecdsa==0.13
enum34==1.1.6
httplib2==0.9.1
idna==2.6
ipaddress==1.0.18
Jinja2==2.10
MarkupSafe==1.0
paramiko==2.4.0
pyasn1==0.4.2
pycparser==2.18
pycrypto==2.6.1
PyNaCl==1.2.0
PyYAML==3.12
six==1.11.0

zamrok@laptop -> ~/rigors/ansible-scripts/ansible-install: [pid 28651] 18:23:43.149192 D mitogen.io: Waker(Broker(0x7fe42c356650) rfd=8, wfd=10).defer() [fd=10]
[pid 28651] 18:23:43.149797 D mitogen.io: EpollPoller(0x7fe42c356890): POLLIN: 8
[pid 28651] 18:23:43.150043 D mitogen.io: Waker(Broker(0x7fe42c356650) rfd=8, wfd=10).on_receive()
[pid 28651] 18:23:43.150973 D mitogen.io: EpollPoller(0x7fe40812ac90): POLLIN: 30
[pid 28651] 18:23:43.151258 I mitogen: mitogen.service.Pool(0x7fe42c356ed0, size=16, th='mitogen.service.Pool.7fe42c356ed0.worker-7'): channel or latch closed, exitting: None
[pid 28651] 18:23:43.151637 D mitogen.io: EpollPoller(0x7fe40812a4d0): POLLIN: 33
[pid 28651] 18:23:43.152090 D mitogen: mitogen.parent.Stream(u'local.28788') closing CALL_FUNCTION channel
[pid 28651] 18:23:43.152360 I mitogen: mitogen.service.Pool(0x7fe42c356ed0, size=16, th='mitogen.service.Pool.7fe42c356ed0.worker-4'): channel or latch closed, exitting: None
[pid 28651] 18:23:43.151788 D mitogen.io: EpollPoller(0x7fe40811f990): POLLIN: 48
[pid 28651] 18:23:43.153168 I mitogen: mitogen.service.Pool(0x7fe42c356ed0, size=16, th='mitogen.service.Pool.7fe42c356ed0.worker-11'): channel or latch closed, exitting: None
[pid 28651] 18:23:43.151887 D mitogen.io: EpollPoller(0x7fe3e643c610): POLLIN: 39
[pid 28651] 18:23:43.154692 I mitogen: mitogen.service.Pool(0x7fe42c356ed0, size=16, th='mitogen.service.Pool.7fe42c356ed0.worker-8'): channel or latch closed, exitting: None
[pid 28651] 18:23:43.155209 D mitogen.io: EpollPoller(0x7fe4081410d0): POLLIN: 18
[pid 28651] 18:23:43.152050 D mitogen.io: EpollPoller(0x7fe40811ff10): POLLIN: 24
[pid 28651] 18:23:43.152267 D mitogen.io: mitogen.parent.Stream(u'local.28788')._send(Message(2024, 0, 0, 106, None, ''..0))
[pid 28651] 18:23:43.152541 D mitogen.io: EpollPoller(0x7fe408141510): POLLIN: 51
[pid 28651] 18:23:43.152599 D mitogen.io: EpollPoller(0x7fe40811f110): POLLIN: 60
[pid 28651] 18:23:43.152640 D mitogen.io: EpollPoller(0x7fe42bafe250): POLLIN: 15
[pid 28651] 18:23:43.156980 I mitogen: mitogen.service.Pool(0x7fe42c356ed0, size=16, th='mitogen.service.Pool.7fe42c356ed0.worker-1'): channel or latch closed, exitting: None
[pid 28651] 18:23:43.156018 D mitogen.io: Broker(0x7fe42c356650)._start_transmit(mitogen.parent.Stream(u'local.28788'))
[pid 28651] 18:23:43.151993 D mitogen.io: EpollPoller(0x7fe408141290): POLLIN: 36
[pid 28651] 18:23:43.157297 I mitogen: mitogen.service.Pool(0x7fe42c356ed0, size=16, th='mitogen.service.Pool.7fe42c356ed0.worker-3'): channel or latch closed, exitting: None
[pid 28651] 18:23:43.156768 D mitogen.io: EpollPoller(0x7fe3e643c790): POLLIN: 45
[pid 28651] 18:23:43.156845 D mitogen.io: EpollPoller(0x7fe3e62f4490): POLLIN: 57
[pid 28651] 18:23:43.158019 I mitogen: mitogen.service.Pool(0x7fe42c356ed0, size=16, th='mitogen.service.Pool.7fe42c356ed0.worker-12'): channel or latch closed, exitting: None
[pid 28651] 18:23:43.157088 D mitogen.io: EpollPoller(0x7fe3e62f6fd0): POLLIN: 27
[pid 28651] 18:23:43.158242 I mitogen: mitogen.service.Pool(0x7fe42c356ed0, size=16, th='mitogen.service.Pool.7fe42c356ed0.worker-0'): channel or latch closed, exitting: None
[pid 28651] 18:23:43.158441 I mitogen: mitogen.service.Pool(0x7fe42c356ed0, size=16, th='mitogen.service.Pool.7fe42c356ed0.worker-5'): channel or latch closed, exitting: None
[pid 28651] 18:23:43.157357 D mitogen.io: EpollPoller(0x7fe40812a050): POLLIN: 42
[pid 28651] 18:23:43.157037 D mitogen.io: EpollPoller(0x7fe40811f390): POLLIN: 54
[pid 28651] 18:23:43.158511 I mitogen: mitogen.service.Pool(0x7fe42c356ed0, size=16, th='mitogen.service.Pool.7fe42c356ed0.worker-15'): channel or latch closed, exitting: None
[pid 28651] 18:23:43.157403 D mitogen.io: EpollPoller(0x7fe3e62f4e90): POLLIN: 21
[pid 28651] 18:23:43.159037 I mitogen: mitogen.service.Pool(0x7fe42c356ed0, size=16, th='mitogen.service.Pool.7fe42c356ed0.worker-10'): channel or latch closed, exitting: None
[pid 28651] 18:23:43.159413 I mitogen: mitogen.service.Pool(0x7fe42c356ed0, size=16, th='mitogen.service.Pool.7fe42c356ed0.worker-14'): channel or latch closed, exitting: None
[pid 28651] 18:23:43.159535 I mitogen: mitogen.service.Pool(0x7fe42c356ed0, size=16, th='mitogen.service.Pool.7fe42c356ed0.worker-6'): channel or latch closed, exitting: None
[pid 28651] 18:23:43.157557 D mitogen.io: EpollPoller(0x7fe42c356890).start_transmit(23, (<Side of mitogen.parent.Stream(u'local.28788') fd 23>, <bound method Stream.on_transmit of mitogen.parent.Stream(u'local.28788')>))
[pid 28651] 18:23:43.159605 I mitogen: mitogen.service.Pool(0x7fe42c356ed0, size=16, th='mitogen.service.Pool.7fe42c356ed0.worker-9'): channel or latch closed, exitting: None
[pid 28651] 18:23:43.161131 D mitogen.io: EpollPoller(0x7fe42c356890)._control(23)
[pid 28651] 18:23:43.160359 I mitogen: mitogen.service.Pool(0x7fe42c356ed0, size=16, th='mitogen.service.Pool.7fe42c356ed0.worker-13'): channel or latch closed, exitting: None
[pid 28651] 18:23:43.160836 I mitogen: mitogen.service.Pool(0x7fe42c356ed0, size=16, th='mitogen.service.Pool.7fe42c356ed0.worker-2'): channel or latch closed, exitting: None
[pid 28651] 18:23:43.161359 D mitogen: Waker(Broker(0x7fe42c356650) rfd=8, wfd=10).on_disconnect()
[pid 28651] 18:23:43.161910 D mitogen.io: Broker(0x7fe42c356650).stop_receive(Waker(Broker(0x7fe42c356650) rfd=8, wfd=10))
[pid 28651] 18:23:43.162046 D mitogen.io: Waker(Broker(0x7fe42c356650) rfd=8, wfd=10).defer() [immediate]
[pid 28651] 18:23:43.162161 D mitogen.io: EpollPoller(0x7fe42c356890).stop_receive(8)
[pid 28651] 18:23:43.162259 D mitogen.io: EpollPoller(0x7fe42c356890)._control(8)
[pid 28651] 18:23:43.162361 D mitogen.io: <Side of Waker(Broker(0x7fe42c356650) rfd=8, wfd=10) fd 8>.close()
[pid 28651] 18:23:43.162471 D mitogen.io: Broker(0x7fe42c356650)._stop_transmit(Waker(Broker(0x7fe42c356650) rfd=8, wfd=10))
[pid 28651] 18:23:43.162567 D mitogen.io: EpollPoller(0x7fe42c356890).stop_transmit(10)
[pid 28651] 18:23:43.162659 D mitogen.io: EpollPoller(0x7fe42c356890)._control(10)
[pid 28651] 18:23:43.162751 D mitogen.io: <Side of Waker(Broker(0x7fe42c356650) rfd=8, wfd=10) fd 10>.close()
[pid 28651] 18:23:43.162883 D mitogen: <mitogen.unix.Listener object at 0x7fe42c356b10>.on_disconnect()
[pid 28651] 18:23:43.163040 D mitogen.io: Broker(0x7fe42c356650).stop_receive(<mitogen.unix.Listener object at 0x7fe42c356b10>)
[pid 28651] 18:23:43.163117 D mitogen.io: Waker(Broker(0x7fe42c356650) rfd=8, wfd=10).defer() [immediate]
[pid 28651] 18:23:43.163191 D mitogen.io: EpollPoller(0x7fe42c356890).stop_receive(14)
[pid 28651] 18:23:43.163271 D mitogen.io: EpollPoller(0x7fe42c356890)._control(14)
[pid 28651] 18:23:43.163360 D mitogen.io: <Side of <mitogen.unix.Listener object at 0x7fe42c356b10> fd 14>.close()
[pid 28651] 18:23:43.163719 D mitogen: mitogen.parent.TtyLogStream(u'ssh.192.168.34.18:22').on_disconnect()
[pid 28651] 18:23:43.163867 D mitogen.io: Broker(0x7fe42c356650).stop_receive(mitogen.parent.TtyLogStream(u'ssh.192.168.34.18:22'))
[pid 28651] 18:23:43.163945 D mitogen.io: Waker(Broker(0x7fe42c356650) rfd=8, wfd=10).defer() [immediate]
[pid 28651] 18:23:43.164017 D mitogen.io: EpollPoller(0x7fe42c356890).stop_receive(17)
[pid 28651] 18:23:43.164083 D mitogen.io: EpollPoller(0x7fe42c356890)._control(17)
[pid 28651] 18:23:43.164156 D mitogen.io: <Side of mitogen.parent.TtyLogStream(u'ssh.192.168.34.18:22') fd 17>.close()
[pid 28651] 18:23:43.164242 D mitogen.io: Broker(0x7fe42c356650)._stop_transmit(mitogen.parent.TtyLogStream(u'ssh.192.168.34.18:22'))
[pid 28651] 18:23:43.164353 D mitogen.io: EpollPoller(0x7fe42c356890).stop_transmit(17)
[pid 28651] 18:23:43.164480 D mitogen.io: EpollPoller(0x7fe42c356890)._control(17)
[pid 28651] 18:23:43.164652 D mitogen: mitogen.ssh.Stream(u'ssh.192.168.34.18:22') closing CALL_FUNCTION channel
[pid 28651] 18:23:43.164808 D mitogen.io: mitogen.ssh.Stream(u'ssh.192.168.34.18:22')._send(Message(2, 0, 0, 106, None, ''..0))
[pid 28651] 18:23:43.164934 D mitogen.io: Broker(0x7fe42c356650)._start_transmit(mitogen.ssh.Stream(u'ssh.192.168.34.18:22'))
[pid 28651] 18:23:43.165053 D mitogen.io: EpollPoller(0x7fe42c356890).start_transmit(66, (<Side of mitogen.ssh.Stream(u'ssh.192.168.34.18:22') fd 66>, <bound method Stream.on_transmit of mitogen.ssh.Stream(u'ssh.192.168.34.18:22')>))
[pid 28651] 18:23:43.165179 D mitogen.io: EpollPoller(0x7fe42c356890)._control(66)
[pid 28651] 18:23:43.165326 D mitogen.io: Broker(0x7fe42c356650)._loop_once(4.999987840652466, EpollPoller(0x7fe42c356890))
[pid 28651] 18:23:43.165465 D mitogen.io: EpollPoller(0x7fe42c356890): POLLIN: 63
[pid 28651] 18:23:43.165576 D mitogen.io: mitogen.ssh.Stream(u'ssh.192.168.34.18:22').on_receive()
[pid 28651] 18:23:43.165760 D mitogen: mitogen.parent.TtyLogStream(u'ssh.192.168.34.18:22').on_disconnect()
[pid 28651] 18:23:43.165966 D mitogen.io: Broker(0x7fe42c356650).stop_receive(mitogen.parent.TtyLogStream(u'ssh.192.168.34.18:22'))
[pid 28651] 18:23:43.166138 D mitogen.io: Waker(Broker(0x7fe42c356650) rfd=8, wfd=10).defer() [immediate]
[pid 28651] 18:23:43.166334 D mitogen.io: EpollPoller(0x7fe42c356890).stop_receive(17)
[pid 28651] 18:23:43.166457 D mitogen.io: EpollPoller(0x7fe42c356890)._control(17)
[pid 28651] 18:23:43.166576 D mitogen.io: Broker(0x7fe42c356650)._stop_transmit(mitogen.parent.TtyLogStream(u'ssh.192.168.34.18:22'))
[pid 28651] 18:23:43.166752 D mitogen.io: EpollPoller(0x7fe42c356890).stop_transmit(17)
[pid 28651] 18:23:43.166869 D mitogen.io: EpollPoller(0x7fe42c356890)._control(17)
[pid 28651] 18:23:43.166997 D mitogen: mitogen.ssh.Stream(u'ssh.192.168.34.18:22'): child process exit status was 33024
[pid 28651] 18:23:43.167137 D mitogen: mitogen.ssh.Stream(u'ssh.192.168.34.18:22').on_disconnect()
[pid 28651] 18:23:43.167280 D mitogen.io: Broker(0x7fe42c356650).stop_receive(mitogen.ssh.Stream(u'ssh.192.168.34.18:22'))
[pid 28651] 18:23:43.167420 D mitogen.io: Waker(Broker(0x7fe42c356650) rfd=8, wfd=10).defer() [immediate]
[pid 28651] 18:23:43.167548 D mitogen.io: EpollPoller(0x7fe42c356890).stop_receive(63)
[pid 28651] 18:23:43.167695 D mitogen.io: EpollPoller(0x7fe42c356890)._control(63)
[pid 28651] 18:23:43.167852 D mitogen.io: <Side of mitogen.ssh.Stream(u'ssh.192.168.34.18:22') fd 63>.close()
[pid 28651] 18:23:43.168005 D mitogen.io: Broker(0x7fe42c356650)._stop_transmit(mitogen.ssh.Stream(u'ssh.192.168.34.18:22'))
[pid 28651] 18:23:43.168191 D mitogen.io: EpollPoller(0x7fe42c356890).stop_transmit(66)
[pid 28651] 18:23:43.168380 D mitogen.io: EpollPoller(0x7fe42c356890)._control(66)
[pid 28651] 18:23:43.168541 D mitogen.io: <Side of mitogen.ssh.Stream(u'ssh.192.168.34.18:22') fd 66>.close()
[pid 28651] 18:23:43.168754 D mitogen: mitogen.ssh.Stream(u'ssh.192.168.34.18:22') is gone; propagating DEL_ROUTE for set([1004, 2, 3, 4])
[pid 28651] 18:23:43.168940 D mitogen: Router(Broker(0x7fe42c356650)).del_route(1004)
[pid 28651] 18:23:43.169242 D mitogen: Router(Broker(0x7fe42c356650)).del_route(2)
[pid 28651] 18:23:43.169397 D mitogen: Router(Broker(0x7fe42c356650)).del_route(3)
[pid 28651] 18:23:43.169527 D mitogen: Router(Broker(0x7fe42c356650)).del_route(4)
[pid 28651] 18:23:43.169737 I ansible_mitogen.services: Dropping Context(2, u'ssh.192.168.34.18:22') due to disconnect of mitogen.ssh.Stream(u'ssh.192.168.34.18:22')
[pid 28651] 18:23:43.169887 I ansible_mitogen.services: Dropping Context(4, u'ssh.192.168.34.18:22.sudo.root') due to disconnect of mitogen.ssh.Stream(u'ssh.192.168.34.18:22')
[pid 28651] 18:23:43.170030 D mitogen.io: EpollPoller(0x7fe42c356890): POLLOUT: 23
[pid 28651] 18:23:43.170186 D mitogen.io: mitogen.parent.Stream(u'local.28788').on_transmit()
[pid 28651] 18:23:43.170328 D mitogen.io: mitogen.parent.Stream(u'local.28788').on_transmit() -> len 24
[pid 28651] 18:23:43.170444 D mitogen.io: Broker(0x7fe42c356650)._stop_transmit(mitogen.parent.Stream(u'local.28788'))
[pid 28651] 18:23:43.170589 D mitogen.io: EpollPoller(0x7fe42c356890).stop_transmit(23)
[pid 28651] 18:23:43.170706 D mitogen.io: EpollPoller(0x7fe42c356890)._control(23)
[pid 28651] 18:23:43.170841 D mitogen.io: Broker(0x7fe42c356650)._loop_once(4.994473934173584, EpollPoller(0x7fe42c356890))
[pid 28651] 18:23:43.173095 D mitogen.io: EpollPoller(0x7fe42c356890): POLLIN: 65
[pid 28651] 18:23:43.173314 D mitogen.io: mitogen.parent.Stream(u'local.28788').on_receive()
[pid 28651] 18:23:43.173498 D mitogen.io: Router(Broker(0x7fe42c356650))._async_route(Message(0, 2024, 2024, 102, 0, "mitogen\x0010\x00mitogen.fork.Stream(u'fork.28791') clos"..75), mitogen.parent.Stream(u'local.28788'))
[pid 28651] 18:23:43.173658 D mitogen.ctx.local.28788: mitogen: mitogen.fork.Stream(u'fork.28791') closing CALL_FUNCTION channel
[pid 28651] 18:23:43.173794 D mitogen.io: Router(Broker(0x7fe42c356650))._async_route(Message(0, 2024, 2024, 102, 0, 'mitogen\x0010\x00Waker(Broker(0x7f8b35f0d910) rfd=3, wfd'..69), mitogen.parent.Stream(u'local.28788'))
[pid 28651] 18:23:43.173933 D mitogen.ctx.local.28788: mitogen: Waker(Broker(0x7f8b35f0d910) rfd=3, wfd=4).on_disconnect()
[pid 28651] 18:23:43.174065 D mitogen.io: Router(Broker(0x7fe42c356650))._async_route(Message(0, 2024, 2024, 102, 0, 'mitogen\x0040\x00<IoLogger stderr> crashed\nTraceback (mo'..278), mitogen.parent.Stream(u'local.28788'))
ERROR! [pid 28651] 18:23:43.174203 E mitogen.ctx.local.28788: mitogen: <IoLogger stderr> crashed
Traceback (most recent call last):
  File "<stdin>", line 1764, in _call
  File "<stdin>", line 1542, in on_receive
  File "<stdin>", line 882, in read
  File "<stdin>", line 287, in io_op
OSError: [Errno 11] Resource temporarily unavailable
[pid 28651] 18:23:43.174388 D mitogen.io: Router(Broker(0x7fe42c356650))._async_route(Message(0, 2024, 2024, 102, 0, 'mitogen\x0010\x00<IoLogger stderr>.on_disconnect()'..44), mitogen.parent.Stream(u'local.28788'))
[pid 28651] 18:23:43.174537 D mitogen.ctx.local.28788: mitogen: <IoLogger stderr>.on_disconnect()
[pid 28651] 18:23:43.174669 D mitogen.io: Router(Broker(0x7fe42c356650))._async_route(Message(0, 2024, 2024, 102, 0, 'mitogen\x0040\x00<IoLogger stdout> crashed\nTraceback (mo'..278), mitogen.parent.Stream(u'local.28788'))
ERROR! [pid 28651] 18:23:43.174805 E mitogen.ctx.local.28788: mitogen: <IoLogger stdout> crashed
Traceback (most recent call last):

[dw]

The fix for this (f7e288f) is on master branch and will make it into the next release. To be updated when a new release is made, subscribe to https://networkgenomics.com/mail/mitogen-announce/

Thanks for reporting this!

[dw]

Sorry -- that fix is for a separate issue. Sorry for closing this prematurely. I'll investigate in the coming days.

[dewthefifth]

No sweat, thanks for looking into it at all.

Honestly, the playbook appears to have executed successfully. It just seems to be hitting a snag while cleaning up connections. If I can provide any additional information to make troubleshooting easier then let me know.

[dw]

You might try a re-run with the latest master, but that stdio fix was for a probably unrelated issue -- subprocesses generating a huge amount of IO could receive errors because the file descriptors were in the wrong mode.

This looks more like WSL is reporting an incorrect errno when the write end of the stdio forwarder pipe is shut down, but I'll need to reproduce it under WSL to be sure.

Thanks again for the report!

[dewthefifth]

I attempted this using the latest master this morning and got the same result.

[dw]

Now I've had time to think about it, this looks suspiciously like a Linux variant of https://github.com/dw/mitogen/issues/320

Both OS X and Linux pollers have an asynchronous event queue decoupled from FD lifetime, so it's very likely the same bug.

If it is simple for you, would you mind trying this: edit "mitogen/parent.py" and delete line ~667, where it reads " 'Linux': EpollPoller," and rerun your job.

Otherwise just wait a few more days and I'll get around to this.

If this is indeed the case, then the bug is basically a manifestation of #26, which entails a poller interface change.

[dw]

Hi there,

How many targets are part of your Ansible run?

[dewthefifth]

There is only one actual target, though the target belongs to a number of groups.

IE

[web-hosts]
target

[database-hosts]
target

[dewthefifth]

Commenting out line 659 of master

'Linux': EpollPoller,

Did not resolve the error

ERROR! [pid 102] 12:15:10.508386 E mitogen.ctx.local.239: mitogen: <IoLogger stderr> crashed
Traceback (most recent call last):
  File "<stdin>", line 1777, in _call
  File "<stdin>", line 1555, in on_receive
  File "<stdin>", line 895, in read
  File "<stdin>", line 287, in io_op
OSError: [Errno 11] Resource temporarily unavailable
ERROR! [pid 102] 12:15:10.510002 E mitogen.ctx.local.239: mitogen: <IoLogger stdout> crashed
Traceback (most recent call last):
  File "<stdin>", line 1777, in _call
  File "<stdin>", line 1555, in on_receive
  File "<stdin>", line 895, in read
  File "<stdin>", line 287, in io_op
OSError: [Errno 11] Resource temporarily unavailable