[q-meta] QuantumClientException: Second simultaneous read on fileno 11 detected

[Nachi Ueno]

When I run quantum + nova in 5 host machine and launch 100 VMs.
I got following exception on the quantum-metadata server.
I'm still not sure the cause, yet

X-Quantum-Router-Id: 2617637b-a3f9-4d0f-8fc5-458bbbfb5d0e __call__ /opt/stack/quantum/quantum/agent/metadata/agent.py:81
2013-03-05 15:28:51.465 5974 ERROR quantum.agent.metadata.agent [-] Unexpected error.
2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent Traceback (most recent call last):
2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent File "/opt/stack/quantum/quantum/agent/metadata/agent.py", line 83, in __call__
2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent instance_id = self._get_instance_id(req)
2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent File "/opt/stack/quantum/quantum/agent/metadata/agent.py", line 111, in _get_instance_id
2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent fixed_ips=['ip_address=%s' % remote_address])['ports']
2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent File "/usr/local/lib/python2.7/dist-packages/quantumclient/v2_0/client.py", line 106, in with_params
2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent ret = self.function(instance, *args, **kwargs)
2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent File "/usr/local/lib/python2.7/dist-packages/quantumclient/v2_0/client.py", line 249, in list_ports
2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent return self.get(self.ports_path, params=_params)
2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent File "/usr/local/lib/python2.7/dist-packages/quantumclient/v2_0/client.py", line 901, in get
2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent headers=headers, params=params)
2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent File "/usr/local/lib/python2.7/dist-packages/quantumclient/v2_0/client.py", line 886, in retry_request
2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent headers=headers, params=params)
2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent File "/usr/local/lib/python2.7/dist-packages/quantumclient/v2_0/client.py", line 831, in do_request
2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent self._handle_fault_response(status_code, replybody)
2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent File "/usr/local/lib/python2.7/dist-packages/quantumclient/v2_0/client.py", line 812, in _handle_fault_response
2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent exception_handler_v20(status_code, des_error_body)
2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent File "/usr/local/lib/python2.7/dist-packages/quantumclient/v2_0/client.py", line 86, in exception_handler_v20
2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent message=message)
2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent QuantumClientException: Second simultaneous read on fileno 11 detected. Unless you really know what you're doing, make sure that only one greenthread can read any particular socket. Consider using a pools.Pool. If you do know what you're doing and want to disable this error, call eventlet.debug.hub_multiple_reader_prevention(False)
2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent
2013-03-05 15:28:51.481 5974 DEBUG quantum.agent.metadata.agent [-] Request: GET /2009-04-04/meta-data/block-device-mapping/Internal HTTP/1.0

[dan wendlandt (danwent)]

adding to RC1 so its on our radar.

[Nachi Ueno (nati-ueno)]

Eventlet logs this error when we try to connect new socket inside of the eventlet thread.
(see http://blog.eventlet.net/2010/03/18/safety/)

This line uses quantum client.
https://github.com/openstack/quantum/blob/master/quantum/agent/metadata/agent.py#L109

The solution looks we should use rpc call here.

[dan wendlandt (danwent)]

why is it that we would need to switch to RPC? I would have thought that we could also make a change to initiate the client within the thread, rather than sharing a single client for the whole instance.

[Nachi Ueno (nati-ueno)]

Hi Dan

You suggestion will work, I'll test it.

[Mark McClain (markmcclain)]

did you try importing the library with:

import eventlet
httplib2 = eventlet.import_patched('httplib2')

If we connect inside each call, that will require a round trip to keystone each time.

[Nachi Ueno (nati-ueno)]

Hi Mark

I have tested both version.

1) create clientj for each api request -> works
2) importlib2 -> not working

2013-03-05 20:45:08.872 4741 ERROR quantum.agent.metadata.agent [-] Unexpected error.
2013-03-05 20:45:08.872 4741 TRACE quantum.agent.metadata.agent Traceback (most recent call last):
2013-03-05 20:45:08.872 4741 TRACE quantum.agent.metadata.agent File "/opt/stack/quantum/quantum/agent/metadata/agent.py", line 83, in __call__
2013-03-05 20:45:08.872 4741 TRACE quantum.agent.metadata.agent instance_id = self._get_instance_id(req)
2013-03-05 20:45:08.872 4741 TRACE quantum.agent.metadata.agent File "/opt/stack/quantum/quantum/agent/metadata/agent.py", line 111, in _get_instance_id
2013-03-05 20:45:08.872 4741 TRACE quantum.agent.metadata.agent fixed_ips=['ip_address=%s' % remote_address])['ports']
2013-03-05 20:45:08.872 4741 TRACE quantum.agent.metadata.agent File "/opt/stack/python-quantumclient/quantumclient/v2_0/client.py", line 106, in with_params
2013-03-05 20:45:08.872 4741 TRACE quantum.agent.metadata.agent ret = self.function(instance, *args, **kwargs)
2013-03-05 20:45:08.872 4741 TRACE quantum.agent.metadata.agent File "/opt/stack/python-quantumclient/quantumclient/v2_0/client.py", line 247, in list_ports
2013-03-05 20:45:08.872 4741 TRACE quantum.agent.metadata.agent return self.get(self.ports_path, params=_params)
2013-03-05 20:45:08.872 4741 TRACE quantum.agent.metadata.agent File "/opt/stack/python-quantumclient/quantumclient/v2_0/client.py", line 848, in get
2013-03-05 20:45:08.872 4741 TRACE quantum.agent.metadata.agent headers=headers, params=params)
2013-03-05 20:45:08.872 4741 TRACE quantum.agent.metadata.agent File "/opt/stack/python-quantumclient/quantumclient/v2_0/client.py", line 833, in retry_request
2013-03-05 20:45:08.872 4741 TRACE quantum.agent.metadata.agent headers=headers, params=params)
2013-03-05 20:45:08.872 4741 TRACE quantum.agent.metadata.agent File "/opt/stack/python-quantumclient/quantumclient/v2_0/client.py", line 778, in do_request
2013-03-05 20:45:08.872 4741 TRACE quantum.agent.metadata.agent self._handle_fault_response(status_code, replybody)
2013-03-05 20:45:08.872 4741 TRACE quantum.agent.metadata.agent File "/opt/stack/python-quantumclient/quantumclient/v2_0/client.py", line 759, in _handle_fault_response
2013-03-05 20:45:08.872 4741 TRACE quantum.agent.metadata.agent exception_handler_v20(status_code, des_error_body)
2013-03-05 20:45:08.872 4741 TRACE quantum.agent.metadata.agent File "/opt/stack/python-quantumclient/quantumclient/v2_0/client.py", line 86, in exception_handler_v20
2013-03-05 20:45:08.872 4741 TRACE quantum.agent.metadata.agent message=message)
2013-03-05 20:45:08.872 4741 TRACE quantum.agent.metadata.agent QuantumClientException: Second simultaneous read on fileno 11 detected. Unless you really know what you're doing, make sure that only one greenthread can read any particular socket. Consider using a pools.Pool. If you do know what you're doing and want to disable this error, call eventlet.debug.hub_multiple_reader_prevention(False)

[dan wendlandt (danwent)]

Yeah, I agree that pulling the client creation closer to use has a lot more
overhead, so let's go for Mark's suggestion.

On Tue, Mar 5, 2013 at 8:34 PM, Mark McClain <email address hidden>wrote:

> did you try importing the library with:
>
> import eventlet
> httplib2 = eventlet.import_patched('httplib2')
>
> If we connect inside each call, that will require a round trip to
> keystone each time.
>
> --
> You received this bug notification because you are a member of Netstack
> Core Developers, which is subscribed to quantum.
> https://bugs.launchpad.net/bugs/1148017
>
> Title:
> [q-meta] QuantumClientException: Second simultaneous read on fileno
> 11 detected
>
> Status in OpenStack Quantum (virtual network service):
> Confirmed
>
> Bug description:
> When I run quantum + nova in 5 host machine and launch 100 VMs.
> I got following exception on the quantum-metadata server.
> I'm still not sure the cause, yet
>
> X-Quantum-Router-Id: 2617637b-a3f9-4d0f-8fc5-458bbbfb5d0e __call__
> /opt/stack/quantum/quantum/agent/metadata/agent.py:81
> 2013-03-05 15:28:51.465 5974 ERROR quantum.agent.metadata.agent [-]
> Unexpected error.
> 2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent
> Traceback (most recent call last):
> 2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent File
> "/opt/stack/quantum/quantum/agent/metadata/agent.py", line 83, in __call__
> 2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent
> instance_id = self._get_instance_id(req)
> 2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent File
> "/opt/stack/quantum/quantum/agent/metadata/agent.py", line 111, in
> _get_instance_id
> 2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent
> fixed_ips=['ip_address=%s' % remote_address])['ports']
> 2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent File
> "/usr/local/lib/python2.7/dist-packages/quantumclient/v2_0/client.py", line
> 106, in with_params
> 2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent ret
> = self.function(instance, *args, **kwargs)
> 2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent File
> "/usr/local/lib/python2.7/dist-packages/quantumclient/v2_0/client.py", line
> 249, in list_ports
> 2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent
> return self.get(self.ports_path, params=_params)
> 2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent File
> "/usr/local/lib/python2.7/dist-packages/quantumclient/v2_0/client.py", line
> 901, in get
> 2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent
> headers=headers, params=params)
> 2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent File
> "/usr/local/lib/python2.7/dist-packages/quantumclient/v2_0/client.py", line
> 886, in retry_request
> 2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent
> headers=headers, params=params)
> 2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent File
> "/usr/local/lib/python2.7/dist-packages/quantumclient/v2_0/client.py", line
> 831, in do_request
> 2013-03-05 15:28:51.465 5974 TRACE quantum.agent.metadata.agent
>...

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/23659

[Nachi Ueno (nati-ueno)]

Hi Dan

httplib2 = eventlet.import_patched('httplib2') looks not working, so I just pushed simple one

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/23659
Committed: http://github.com/openstack/quantum/commit/84ed1079c87717ddd279597fb7b41f5ea29599c8
Submitter: Jenkins
Branch: master

commit 84ed1079c87717ddd279597fb7b41f5ea29599c8
Author: Nachi Ueno <email address hidden>
Date: Tue Mar 5 20:52:22 2013 -0800

    Create quantum client for each api request in metadata agent

    Fixes bug 1148017

    Change-Id: I6f9263f01d17dcc44a4deb42cdaa348164ac4819

[Akihiro Motoki (amotoki)]

Though the fix is merged, there is a point to be improved in the future.

To track the status, I filed separate bugs:
https://bugs.launchpad.net/quantum/+bug/1152429
https://bugs.launchpad.net/python-quantumclient/+bug/1152427