This is caused by the server erroneously assuming the l2 agent is down. See the traces where binding fails because the agent is marked down, but then is assumed back on line.

This is due to poor settings of report and timeout intervals.


2013-11-01 21:13:35.261 2769 DEBUG neutron.plugins.ml2.drivers.mech_agent [-] Checking agent: {'binary': u'neutron-openvswitch-agent', 'description': None, 'admin_state_up': True, 'heartbeat_timestamp': datetime.datetime(2013, 11, 1, 21, 13, 30), 'alive': False, 'topic': u'N/A', 'host': u'devstack-precise-hpcloud-az1-631654', 'agent_type': u'Open vSwitch agent', 'created_at': datetime.datetime(2013, 11, 1, 21, 5, 42), 'started_at': datetime.datetime(2013, 11, 1, 21, 5, 42), 'id': u'3acf236a-589a-4f51-be43-9b6f19d0ba70', 'configurations': {u'tunnel_types': [], u'tunneling_ip': u'10.5.153.104', u'bridge_mappings': {}, u'l2_population': False, u'devices': 14}} bind_port /opt/stack/new/neutron/neutron/plugins/ml2/drivers/mech_agent.py:59
2013-11-01 21:13:35.268 2769 WARNING neutron.plugins.ml2.drivers.mech_agent [-] Attempting to bind with dead agent: {'binary': u'neutron-openvswitch-agent', 'description': None, 'admin_state_up': True, 'heartbeat_timestamp': datetime.datetime(2013, 11, 1, 21, 13, 30), 'alive': False, 'topic': u'N/A', 'host': u'devstack-precise-hpcloud-az1-631654', 'agent_type': u'Open vSwitch agent', 'created_at': datetime.datetime(2013, 11, 1, 21, 5, 42), 'started_at': datetime.datetime(2013, 11, 1, 21, 5, 42), 'id': u'3acf236a-589a-4f51-be43-9b6f19d0ba70', 'configurations': {u'tunnel_types': [], u'tunneling_ip': u'10.5.153.104', u'bridge_mappings': {}, u'l2_population': False, u'devices': 14}}
2013-11-01 21:13:35.268 2769 DEBUG neutron.plugins.ml2.drivers.mech_agent [-] Attempting to bind port f5129205-db1b-46e5-bef5-e9a1abb114c5 on network 692d1116-107a-4c04-be6a-7fff7b47334e bind_port /opt/stack/new/neutron/neutron/plugins/ml2/drivers/mech_agent.py:57
2013-11-01 21:13:35.271 2769 WARNING neutron.plugins.ml2.managers [-] Failed to bind port f5129205-db1b-46e5-bef5-e9a1abb114c5 on host devstack-precise-hpcloud-az1-631654
2013-11-01 21:13:35.287 2769 DEBUG neutron.openstack.common.rpc.amqp [-] received {u'_context_roles': [u'admin'], u'_context_read_deleted': u'no', u'_context_tenant_id': None, u'args': {u'agent_state': {u'agent_state': {u'topic': u'l3_agent', u'binary': u'neutron-l3-agent', u'host': u'devstack-precise-hpcloud-az1-631654', u'agent_type': u'L3 agent', u'configurations': {u'router_id': u'', u'gateway_external_network_id': u'', u'handle_internal_only_routers': True, u'use_namespaces': True, u'routers': 4, u'interfaces': 4, u'floating_ips': 0, u'interface_driver': u'neutron.agent.linux.interface.OVSInterfaceDriver', u'ex_gw_ports': 4}}}, u'time': u'2013-11-01T21:13:34.989761'}, u'namespace': None, u'_unique_id': u'989343937ab34d1190b68be196187860', u'_context_is_admin': True, u'version': u'1.0', u'_context_project_id': None, u'_context_timestamp': u'2013-11-01 21:05:42.202105', u'_context_user_id': None, u'method': u'report_state'} _safe_log /opt/stack/new/neutron/neutron/openstack/common/rpc/common.py:276
2013-11-01 21:13:35.287 2769 DEBUG neutron.openstack.common.rpc.amqp [-] unpacked context: {'user_id': None, 'roles': [u'admin'], 'tenant_id': None, 'is_admin': True, 'timestamp': u'2013-11-01 21:05:42.202105', 'project_id': None, 'read_deleted': u'no'} _safe_log /opt/stack/new/neutron/neutron/openstack/common/rpc/common.py:276
2013-11-01 21:13:35.288 2769 DEBUG neutron.openstack.common.rpc.amqp [-] received {u'_context_roles': [u'admin'], u'_msg_id': u'396f5a60840f474cb71158699f79138d', u'_context_read_deleted': u'no', u'_reply_q': u'reply_926525fdb4a343479eebbe6367d863cc', u'_context_tenant_id': None, u'args': {u'devices': [u'ad5058d2-fc8f-4250-a6d1-f41ae7b0c5f1', u'c7926ee9-4f82-4a94-8c67-6c8fa255549b']}, u'namespace': None, u'_unique_id': u'84eda351118c4c8386360899de40e442', u'_context_is_admin': True, u'version': u'1.1', u'_context_project_id': None, u'_context_timestamp': u'2013-11-01 21:05:42.577872', u'_context_user_id': None, u'method': u'security_group_rules_for_devices'} _safe_log /opt/stack/new/neutron/neutron/openstack/common/rpc/common.py:276
2013-11-01 21:13:35.288 2769 DEBUG neutron.openstack.common.rpc.amqp [-] unpacked context: {'user_id': None, 'roles': [u'admin'], 'tenant_id': None, 'is_admin': True, 'timestamp': u'2013-11-01 21:05:42.577872', 'project_id': None, 'read_deleted': u'no'} _safe_log /opt/stack/new/neutron/neutron/openstack/common/rpc/common.py:276
2013-11-01 21:13:35.289 2769 DEBUG neutron.openstack.common.rpc.amqp [-] received {u'_context_roles': [u'admin'], u'_msg_id': u'72368fedbe4f42348206ad8e1d40adb0', u'_context_read_deleted': u'no', u'_reply_q': u'reply_926525fdb4a343479eebbe6367d863cc', u'_context_tenant_id': None, u'args': {u'devices': [u'ad5058d2-fc8f-4250-a6d1-f41ae7b0c5f1', u'c7926ee9-4f82-4a94-8c67-6c8fa255549b']}, u'namespace': None, u'_unique_id': u'22a222f31d6e4f86a8136d0290fe7d15', u'_context_is_admin': True, u'version': u'1.1', u'_context_project_id': None, u'_context_timestamp': u'2013-11-01 21:05:42.577872', u'_context_user_id': None, u'method': u'security_group_rules_for_devices'} _safe_log /opt/stack/new/neutron/neutron/openstack/common/rpc/common.py:276
2013-11-01 21:13:35.289 2769 DEBUG neutron.openstack.common.rpc.amqp [-] unpacked context: {'user_id': None, 'roles': [u'admin'], 'tenant_id': None, 'is_admin': True, 'timestamp': u'2013-11-01 21:05:42.577872', 'project_id': None, 'read_deleted': u'no'} _safe_log /opt/stack/new/neutron/neutron/openstack/common/rpc/common.py:276
2013-11-01 21:13:35.290 2769 DEBUG neutron.openstack.common.rpc.amqp [-] received {u'_context_roles': [u'admin'], u'_context_read_deleted': u'no', u'_context_tenant_id': None, u'args': {u'agent_state': {u'agent_state': {u'topic': u'lbaas_process_on_host_agent', u'binary': u'neutron-loadbalancer-agent', u'host': u'devstack-precise-hpcloud-az1-631654', u'agent_type': u'Loadbalancer agent', u'configurations': {u'device_driver': u'neutron.services.loadbalancer.drivers.haproxy.namespace_driver.HaproxyNSDriver', u'interface_driver': u'neutron.agent.linux.interface.OVSInterfaceDriver', u'devices': 0}}}, u'time': u'2013-11-01T21:13:35.052944'}, u'namespace': None, u'_unique_id': u'76c20d1c697c4713914740cc4aa1ba05', u'_context_is_admin': True, u'version': u'1.0', u'_context_project_id': None, u'_context_timestamp': u'2013-11-01 21:05:42.790815', u'_context_user_id': None, u'method': u'report_state'} _safe_log /opt/stack/new/neutron/neutron/openstack/common/rpc/common.py:276
2013-11-01 21:13:35.290 2769 DEBUG neutron.openstack.common.rpc.amqp [-] unpacked context: {'user_id': None, 'roles': [u'admin'], 'tenant_id': None, 'is_admin': True, 'timestamp': u'2013-11-01 21:05:42.790815', 'project_id': None, 'read_deleted': u'no'} _safe_log /opt/stack/new/neutron/neutron/openstack/common/rpc/common.py:276
2013-11-01 21:13:35.290 2769 DEBUG neutron.openstack.common.rpc.amqp [-] Making asynchronous fanout cast... fanout_cast /opt/stack/new/neutron/neutron/openstack/common/rpc/amqp.py:568
2013-11-01 21:13:35.291 2769 DEBUG neutron.openstack.common.rpc.amqp [-] UNIQUE_ID is b478346c3d9546abba37ce7ea3fe6219. _add_unique_id /opt/stack/new/neutron/neutron/openstack/common/rpc/amqp.py:339
2013-11-01 21:13:35.295 2769 DEBUG neutron.plugins.ml2.db [-] get_port_and_sgs() called for port_id ad5058d2-fc8f-4250-a6d1-f41ae7b0c5f1 get_port_and_sgs /opt/stack/new/neutron/neutron/plugins/ml2/db.py:99
2013-11-01 21:13:35.316 2769 DEBUG neutron.plugins.ml2.db [-] get_port_and_sgs() called for port_id ad5058d2-fc8f-4250-a6d1-f41ae7b0c5f1 get_port_and_sgs /opt/stack/new/neutron/neutron/plugins/ml2/db.py:99
2013-11-01 21:13:35.348 2769 DEBUG neutron.plugins.ml2.db [-] get_port_and_sgs() called for port_id c7926ee9-4f82-4a94-8c67-6c8fa255549b get_port_and_sgs /opt/stack/new/neutron/neutron/plugins/ml2/db.py:99
2013-11-01 21:13:35.369 2769 DEBUG neutron.plugins.ml2.db [-] get_port_and_sgs() called for port_id c7926ee9-4f82-4a94-8c67-6c8fa255549b get_port_and_sgs /opt/stack/new/neutron/neutron/plugins/ml2/db.py:99
2013-11-01 21:13:35.396 2769 DEBUG neutron.api.v2.base [-] Policy rule:get_port:allowed_address_pairs not found. Assuming no authZ check is defined for allowed_address_pairs _is_visible /opt/stack/new/neutron/neutron/api/v2/base.py:143
2013-11-01 21:13:35.397 2769 DEBUG neutron.api.v2.base [-] Policy rule:get_port:fixed_ips not found. Assuming no authZ check is defined for fixed_ips _is_visible /opt/stack/new/neutron/neutron/api/v2/base.py:143
2013-11-01 21:13:35.397 2769 DEBUG neutron.api.v2.base [-] Policy rule:get_port:mac_address not found. Assuming no authZ check is defined for mac_address _is_visible /opt/stack/new/neutron/neutron/api/v2/base.py:143
2013-11-01 21:13:35.397 2769 DEBUG neutron.openstack.common.rpc.amqp [-] Sending port.create.end on notifications.info notify /opt/stack/new/neutron/neutron/openstack/common/rpc/amqp.py:598
2013-11-01 21:13:35.398 2769 DEBUG neutron.openstack.common.rpc.amqp [-] UNIQUE_ID is 281fe87a3c79401e8b142a54bb238d65. _add_unique_id /opt/stack/new/neutron/neutron/openstack/common/rpc/amqp.py:339
2013-11-01 21:13:35.524 2769 DEBUG neutron.openstack.common.rpc.amqp [-] UNIQUE_ID is 502d6df574bf4dbbb9ac72bfca027b91. _add_unique_id /opt/stack/new/neutron/neutron/openstack/common/rpc/amqp.py:339
2013-11-01 21:13:35.525 2769 DEBUG neutron.openstack.common.rpc.amqp [-] UNIQUE_ID is eb2a3fbf82734a9aab30e127270462f3. _add_unique_id /opt/stack/new/neutron/neutron/openstack/common/rpc/amqp.py:339
2013-11-01 21:13:35.568 2769 DEBUG neutron.scheduler.dhcp_agent_scheduler [-] Network 692d1116-107a-4c04-be6a-7fff7b47334e is scheduled to be hosted by DHCP agent <neutron.db.agents_db.Agent[object at 40a92d0] {id=u'acd1a6c3-45f4-47a4-9fe2-a95b780c536d', agent_type=u'DHCP agent', binary=u'neutron-dhcp-agent', topic=u'dhcp_agent', host=u'devstack-precise-hpcloud-az1-631654', admin_state_up=True, created_at=datetime.datetime(2013, 11, 1, 21, 5, 42), started_at=datetime.datetime(2013, 11, 1, 21, 5, 42), heartbeat_timestamp=datetime.datetime(2013, 11, 1, 21, 13, 34), description=None, configurations=u'{"subnets": 1, "use_namespaces": true, "dhcp_lease_duration": 86400, "dhcp_driver": "neutron.agent.linux.dhcp.Dnsmasq", "networks": 1, "ports": 3}'}> _schedule_bind_network /opt/stack/new/neutron/neutron/scheduler/dhcp_agent_scheduler.py:45
2013-11-01 21:13:35.576 2769 DEBUG neutron.openstack.common.rpc.amqp [-] Making asynchronous cast on dhcp_agent.devstack-precise-hpcloud-az1-631654... cast /opt/stack/new/neutron/neutron/openstack/common/rpc/amqp.py:559
2013-11-01 21:13:35.577 2769 DEBUG neutron.openstack.common.rpc.amqp [-] UNIQUE_ID is 832bb636d7924b149374ac6ce1f80c2d. _add_unique_id /opt/stack/new/neutron/neutron/openstack/common/rpc/amqp.py:339
2013-11-01 21:13:35.577 2769 DEBUG neutron.openstack.common.rpc.amqp [-] UNIQUE_ID is 05a812f3baf244a7a7a6b69c5a248d18. _add_unique_id /opt/stack/new/neutron/neutron/openstack/common/rpc/amqp.py:339
2013-11-01 21:13:35.578 2769 DEBUG neutron.openstack.common.rpc.amqp [-] UNIQUE_ID is e18db00a74274c578d513d524b6d6259. _add_unique_id /opt/stack/new/neutron/neutron/openstack/common/rpc/amqp.py:339
2013-11-01 21:13:35.585 2769 DEBUG neutron.openstack.common.rpc.amqp [-] Making asynchronous cast on dhcp_agent.devstack-precise-hpcloud-az1-631654... cast /opt/stack/new/neutron/neutron/openstack/common/rpc/amqp.py:559
2013-11-01 21:13:35.586 2769 DEBUG neutron.openstack.common.rpc.amqp [-] UNIQUE_ID is bc6c6107047d433d928fc364eb354011. _add_unique_id /opt/stack/new/neutron/neutron/openstack/common/rpc/amqp.py:339
2013-11-01 21:13:35.594 2769 DEBUG neutron.openstack.common.rpc.amqp [-] received {u'_context_roles': [u'admin'], u'_msg_id': u'f571dbd86b394c598c4f768ab4212dc8', u'_context_read_deleted': u'no', u'_reply_q': u'reply_98817249593d45a38b11774e09dfa0b8', u'_context_tenant_id': None, u'args': {u'network_id': u'692d1116-107a-4c04-be6a-7fff7b47334e', u'host': u'devstack-precise-hpcloud-az1-631654'}, u'namespace': None, u'_unique_id': u'a229534358e14f9a99b393cc30583e11', u'_context_is_admin': True, u'version': u'1.1', u'_context_project_id': None, u'_context_timestamp': u'2013-11-01 21:05:42.176674', u'_context_user_id': None, u'method': u'get_network_info'} _safe_log /opt/stack/new/neutron/neutron/openstack/common/rpc/common.py:276
2013-11-01 21:13:35.594 2769 DEBUG neutron.openstack.common.rpc.amqp [-] unpacked context: {'user_id': None, 'roles': [u'admin'], 'tenant_id': None, 'is_admin': True, 'timestamp': u'2013-11-01 21:05:42.176674', 'project_id': None, 'read_deleted': u'no'} _safe_log /opt/stack/new/neutron/neutron/openstack/common/rpc/common.py:276
2013-11-01 21:13:35.595 2769 DEBUG neutron.db.dhcp_rpc_base [-] Network 692d1116-107a-4c04-be6a-7fff7b47334e requested from devstack-precise-hpcloud-az1-631654 get_network_info /opt/stack/new/neutron/neutron/db/dhcp_rpc_base.py:83
2013-11-01 21:13:35.605 2769 INFO neutron.wsgi [-] 127.0.0.1 - - [01/Nov/2013 21:13:35] "POST /v2.0/ports.json HTTP/1.1" 201 795 0.731305

2013-11-01 21:13:35.654 2769 DEBUG neutron.openstack.common.rpc.amqp [-] UNIQUE_ID is ff0cf35df55d47b0a696409f1b9023d0. _add_unique_id /opt/stack/new/neutron/neutron/openstack/common/rpc/amqp.py:339
2013-11-01 21:13:35.659 2769 DEBUG neutron.openstack.common.rpc.amqp [-] UNIQUE_ID is 1bd497dbc74947c79a9be04a40618cf8. _add_unique_id /opt/stack/new/neutron/neutron/openstack/common/rpc/amqp.py:339
2013-11-01 21:13:35.667 2769 DEBUG neutron.openstack.common.rpc.amqp [-] received {u'_context_roles': [u'admin'], u'_msg_id': u'c02c2f861a4a47af9af800c33e97a19f', u'_context_read_deleted': u'no', u'_reply_q': u'reply_98817249593d45a38b11774e09dfa0b8', u'_context_tenant_id': None, u'args': {u'host': u'devstack-precise-hpcloud-az1-631654', u'port': {u'port': {u'name': u'', u'admin_state_up': True, u'network_id': u'692d1116-107a-4c04-be6a-7fff7b47334e', u'tenant_id': u'd688c2c8a7c94558a7d5422c9561299e', u'fixed_ips': [{u'subnet_id': u'5106254a-da9a-488a-8ca1-502cbc8864d8'}], u'device_id': u'dhcpcc527bee-52e2-5453-b8c5-f00e8fb0e29b-692d1116-107a-4c04-be6a-7fff7b47334e'}}}, u'namespace': None, u'_unique_id': u'a3a72e593ced4386ba3db530a408e567', u'_context_is_admin': True, u'version': u'1.1', u'_context_project_id': None, u'_context_timestamp': u'2013-11-01 21:05:42.176674', u'_context_user_id': None, u'method': u'create_dhcp_port'} _safe_log /opt/stack/new/neutron/neutron/openstack/common/rpc/common.py:276
2013-11-01 21:13:35.667 2769 DEBUG neutron.openstack.common.rpc.amqp [-] unpacked context: {'user_id': None, 'roles': [u'admin'], 'tenant_id': None, 'is_admin': True, 'timestamp': u'2013-11-01 21:05:42.176674', 'project_id': None, 'read_deleted': u'no'} _safe_log /opt/stack/new/neutron/neutron/openstack/common/rpc/common.py:276
2013-11-01 21:13:35.668 2769 DEBUG neutron.db.dhcp_rpc_base [-] Create dhcp port {u'port': {u'name': u'', u'admin_state_up': True, u'network_id': u'692d1116-107a-4c04-be6a-7fff7b47334e', u'tenant_id': u'd688c2c8a7c94558a7d5422c9561299e', u'fixed_ips': [{u'subnet_id': u'5106254a-da9a-488a-8ca1-502cbc8864d8'}], u'device_id': u'dhcpcc527bee-52e2-5453-b8c5-f00e8fb0e29b-692d1116-107a-4c04-be6a-7fff7b47334e'}} from devstack-precise-hpcloud-az1-631654. create_dhcp_port /opt/stack/new/neutron/neutron/db/dhcp_rpc_base.py:225
2013-11-01 21:13:35.689 2769 DEBUG neutron.db.db_base_plugin_v2 [-] Generated mac for network 692d1116-107a-4c04-be6a-7fff7b47334e is fa:16:3e:fa:2c:21 _generate_mac /opt/stack/new/neutron/neutron/db/db_base_plugin_v2.py:302
2013-11-01 21:13:35.705 2769 DEBUG neutron.db.db_base_plugin_v2 [-] Allocated IP - 10.100.0.3 from 10.100.0.3 to 10.100.0.254 _generate_ip /opt/stack/new/neutron/neutron/db/db_base_plugin_v2.py:473
2013-11-01 21:13:35.705 2769 DEBUG neutron.db.db_base_plugin_v2 [-] Allocated IP 10.100.0.3 (692d1116-107a-4c04-be6a-7fff7b47334e/5106254a-da9a-488a-8ca1-502cbc8864d8/febede91-527e-42d6-923e-b358642f9839) create_port /opt/stack/new/neutron/neutron/db/db_base_plugin_v2.py:1360
2013-11-01 21:13:35.750 2769 DEBUG neutron.plugins.ml2.managers [-] Attempting to bind port febede91-527e-42d6-923e-b358642f9839 on host devstack-precise-hpcloud-az1-631654 bind_port /opt/stack/new/neutron/neutron/plugins/ml2/managers.py:440
2013-11-01 21:13:35.751 2769 DEBUG neutron.plugins.ml2.drivers.mech_agent [-] Attempting to bind port febede91-527e-42d6-923e-b358642f9839 on network 692d1116-107a-4c04-be6a-7fff7b47334e bind_port /opt/stack/new/neutron/neutron/plugins/ml2/drivers/mech_agent.py:57
2013-11-01 21:13:35.755 2769 DEBUG neutron.plugins.ml2.drivers.mech_agent [-] Checking agent: {'binary': u'neutron-openvswitch-agent', 'description': None, 'admin_state_up': True, 'heartbeat_timestamp': datetime.datetime(2013, 11, 1, 21, 13, 35), 'alive': True, 'topic': u'N/A', 'host': u'devstack-precise-hpcloud-az1-631654', 'agent_type': u'Open vSwitch agent', 'created_at': datetime.datetime(2013, 11, 1, 21, 5, 42), 'started_at': datetime.datetime(2013, 11, 1, 21, 5, 42), 'id': u'3acf236a-589a-4f51-be43-9b6f19d0ba70', 'configurations': {u'tunnel_types': [], u'tunneling_ip': u'10.5.153.104', u'bridge_mappings': {}, u'l2_population': False, u'devices': 14}} bind_port /opt/stack/new/neutron/neutron/plugins/ml2/drivers/mech_agent.py:59
2013-11-01 21:13:35.755 2769 DEBUG neutron.plugins.ml2.drivers.mech_openvswitch [-] Checking segment: {'segmentation_id': None, 'physical_network': None, 'id': u'd3f1c48d-8e8f-4a2b-91fe-7fc777138bb4', 'network_type': u'local'} for mappings: {} with tunnel_types: [] check_segment_for_agent /opt/stack/new/neutron/neutron/plugins/ml2/drivers/mech_openvswitch.py:48
2013-11-01 21:13:35.755 2769 DEBUG neutron.plugins.ml2.drivers.mech_agent [-] Bound using segment: {'segmentation_id': None, 'physical_network': None, 'id': u'd3f1c48d-8e8f-4a2b-91fe-7fc777138bb4', 'network_type': u'local'} bind_port /opt/stack/new/neutron/neutron/plugins/ml2/drivers/mech_agent.py:66
2013-11-01 21:13:35.756 2769 DEBUG neutron.plugins.ml2.managers [-] Bound port: febede91-527e-42d6-923e-b358642f9839, host: devstack-precise-hpcloud-az1-631654, driver: openvswitch, vif_type: ovs, cap_port_filter: True, segment: d3f1c48d-8e8f-4a2b-91fe-7fc777138bb4 bind_port /opt/stack/new/neutron/neutron/plugins/ml2/managers.py:455
2013-11-01 21:13:35.758 2769 INFO neutron.wsgi [-] (2769) accepted ('127.0.0.1', 36993)