Service pool lock must be held and reinitialized across fork

[jrosser]

From an OSA AIO deploy, an async task....

TASK [os_horizon : Compile messages for translation] *********************************************************************************************************************************
ok: [aio1_horizon_container-bfb96d25] => (item=/openstack/venvs/horizon-19.0.0.0b1/lib/python2.7/dist-packages/horizon)
ok: [aio1_horizon_container-bfb96d25] => (item=/openstack/venvs/horizon-19.0.0.0b1/lib/python2.7/dist-packages/openstack_dashboard)
ERROR! [pid 21444] 17:12:49.261466 E mitogen: Received DEL_ROUTE for 107138 from mitogen.setns.Stream(u'setns.aio1_horizon_container-bfb96d25'), expected None
ERROR! [pid 21444] 17:12:49.262085 E mitogen.ctx.setns.aio1_horizon_container-bfb96d25: mitogen: Received DEL_ROUTE for 107138 from mitogen.sudo.Stream(u'sudo.horizon'), expected mitogen.core.Stream('parent')
ERROR! [pid 21444] 17:12:49.262392 E mitogen.ctx.setns.aio1_horizon_container-bfb96d25.sudo.horizon: mitogen: Received DEL_ROUTE for 107138 from mitogen.fork.Stream(u'fork.1309'), expected mitogen.core.Stream('parent')

TASK [os_horizon : Ensure messages are compiled for translation] *********************************************************************************************************************
changed: [aio1_horizon_container-bfb96d25] => (item={'_ansible_parsed': True, '_ansible_item_result': True, '_ansible_no_log': False, u'ansible_job_id': u'171d24cb4603029a', 'failed': False, u'started': 1, u'changed': False, 'item': u'/openstack/venvs/horizon-19.0.0.0b1/lib/python2.7/dist-packages/horizon', u'finished': 0, '_ansible_ignore_errors': None, '_ansible_item_label': u'/openstack/venvs/horizon-19.0.0.0b1/lib/python2.7/dist-packages/horizon'})
FAILED - RETRYING: Ensure messages are compiled for translation (300 retries left).
FAILED - RETRYING: Ensure messages are compiled for translation (299 retries left).
FAILED - RETRYING: Ensure messages are compiled for translation (298 retries left).
FAILED - RETRYING: Ensure messages are compiled for translation (297 retries left).
FAILED - RETRYING: Ensure messages are compiled for translation (296 retries left).
FAILED - RETRYING: Ensure messages are compiled for translation (295 retries left).

Retries 300 times and fails.

These are the tasks in question:

https://github.com/openstack/openstack-ansible-os_horizon/blob/3d60097f94b8a27eabcfd931d4f80a9d8f2b7280/tasks/horizon_post_install.yml#L110

https://github.com/openstack/openstack-ansible-os_horizon/blob/4283200534eafa444efd9bb408ddcb5c98a1d442/tasks/main.yml#L105

[dw]

Hi Johnathan!

Could you see from the target whether the process was still running? Async is quite icky because it touches the filesystem -- maybe it failed to write the job status file, still investigating.

Thanks for reporting this

[dw]

Yowzer, that's a fun one, it's creating those tasks in a loop.. https://github.com/openstack/openstack-ansible-os_horizon/blob/4283200534eafa444efd9bb408ddcb5c98a1d442/tasks/horizon_post_install.yml#L124

At least that is something to write a test case for. I'm curious if the async tasks are sensible to begin with.. does compress not need to wait for collectstatic to finish?

[dw]

The error messages are a red herring (#413). I've reproduced it locally. Enabling MITOGEN_ROUTER_DEBUG=1 makes the jobs succeed. Very interesting

[dw]

Ah! Has this only started occurring on recent masters?

[jrosser]

Sadly this failure was in CI so I didn't get to investigate it directly. I'm not sure where this started occurring as your recent changes to mitogen have made the OSA build get quite some way further than it did before.

Also, as far as I can see from a successful run, the "Ensure messages are compiled for translation" didn't have to wait very long for the completion of the async task, it might be worth adding another item to your test case which finishes instantaneously so that it is ready before the async_status task is run.

[dw]

Fairly sure the same issue is showing up on Travis, issue #425

[dw]

MO:

• must be a loop of async tasks like your example
• must be over SSH + sudo, local subprocess isn't enough to tickle it (why?)
• all tasks progress except once which sits idle after writing its status file
• strace shows a potential deadlock:

proc]# strace -ff -p 29858
strace: Process 29858 attached with 3 threads
[pid 29864] futex(0x55ea9be52f60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, 0xffffffff <unfinished ...>
[pid 29860] restart_syscall(<... resuming interrupted poll ...> <unfinished ...>
[pid 29858] futex(0x55ea9be52f60, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, 0xffffffff

• 29860 looks like the broker thread, it's asleep in poll and seemingly happy, so the lock is probably not one of the safe-to-take-in-async locks
• remaining two threads are blocked waiting for the same lock
• thread A is the main thread, it's the function call dispatcher
• 29864 I think must either be a service pool worker (but I think there should be 8 of those), or the transient thread created to start the service pool on first request

[dw]

It's the service pool initialization lock.

Sequence is:

• controller writes a file to the target account (this is the only master->controller service)
• stub CALL_SERVICE handler registered by the bootstrap is called back on the broker thread
• can't do anything with the message on the broker thread, because we can't deserialize there and can't use the importer there (since it needs the broker to run)
• so fire a thread that keeps a copy of the message in its args for a safe place to import from
• that thread calls get_or_init_pool(), which takes the lock to prevent any other such threads running
• controller starts an async task by asking dispatcher thread to fork
• newly forked async task gets a snapshot of memory with the pool lock held
• everything reinits, except the pool lock

no clue what is causing the main thread to block on it too, doesn't matter, problem is that service pool lock isn't part of the cleanups done by on_fork().

There are actually 2 locks in play here: the importer lock can cause trouble too. It's already documented "no imports off the main thread", but I broke my own rule. Solution is taking the service pool lock during fork and discarding it after fork, and recording in the docs this is done to prevent off-main-thread import lock acquisition