neutron

broken pipe errors cause neutron metadata agent to fail

Bug #1855919 reported by Albert Braden on 2019-12-10

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	neutron	Fix Released	Low	Unassigned

Bug Description

After we increased computes to 200, we started seeing "broken pipe" errors in neutron-metadata-agent.log on the controllers. After a neutron restart the errors are reduced, then they increase until the log is mostly errors, and the neutron metadata service fails, and VMs cannot boot. Another symptom is that unacked RMQ messages build up in the q-plugin queue. This is the first error we see; this one occurs as the server is starting:

2019-12-10 10:56:01.942 1838536 INFO eventlet.wsgi.server [-] (1838536) wsgi starting up on http:/var/lib/neutron/metadata_proxy
2019-12-10 10:56:01.943 1838538 INFO eventlet.wsgi.server [-] (1838538) wsgi starting up on http:/var/lib/neutron/metadata_proxy
2019-12-10 10:56:01.945 1838539 INFO eventlet.wsgi.server [-] (1838539) wsgi starting up on http:/var/lib/neutron/metadata_proxy
2019-12-10 10:56:21.138 1838538 INFO eventlet.wsgi.server [-] Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/eventlet/wsgi.py", line 521, in handle_one_response
    write(b''.join(towrite))
  File "/usr/lib/python2.7/dist-packages/eventlet/wsgi.py", line 462, in write
    wfile.flush()
  File "/usr/lib/python2.7/socket.py", line 307, in flush
    self._sock.sendall(view[write_offset:write_offset+buffer_size])
  File "/usr/lib/python2.7/dist-packages/eventlet/greenio/base.py", line 390, in sendall
    tail = self.send(data, flags)
  File "/usr/lib/python2.7/dist-packages/eventlet/greenio/base.py", line 384, in send
    return self._send_loop(self.fd.send, data, flags)
  File "/usr/lib/python2.7/dist-packages/eventlet/greenio/base.py", line 371, in _send_loop
    return send_method(data, *args)
error: [Errno 32] Broken pipe

2019-12-10 10:56:21.138 1838538 INFO eventlet.wsgi.server [-] 10.195.74.25,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200 len: 0 time: 19.0296111
2019-12-10 10:56:25.059 1838516 INFO eventlet.wsgi.server [-] 10.195.74.28,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200 len: 146 time: 0.2840948
2019-12-10 10:56:25.181 1838529 INFO eventlet.wsgi.server [-] 10.195.74.68,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200 len: 146 time: 0.2695429
2019-12-10 10:56:25.259 1838518 INFO eventlet.wsgi.server [-] 10.195.74.28,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200 len: 146 time: 0.1980510

Then we see some "call queues" warnings and the threshold increases to 40:

2019-12-10 10:56:31.414 1838515 WARNING oslo_messaging._drivers.amqpdriver [-] Number of call queues is 11, greater than warning threshold: 10. There could be a leak. Increasing threshold to: 20

Next we see RPC timeout errors:

2019-12-10 10:57:02.043 1838520 WARNING oslo_messaging._drivers.amqpdriver [-] Number of call queues is 11, greater than warning threshold: 10. There could be a leak. Increasing threshold to: 20
2019-12-10 10:57:02.059 1838534 ERROR neutron.common.rpc [-] Timeout in RPC method get_ports. Waiting for 37 seconds before next attempt. If the server is not down, consider increasing the rpc_response_timeout option as Neutron server(s) may be overloaded and unable to respond quickly enough.: MessagingTimeout: Timed out waiting for a reply to message ID 1ed3e021607e466f8b9b84cd3b05b188
2019-12-10 10:57:02.059 1838534 WARNING neutron.common.rpc [-] Increasing timeout for get_ports calls to 120 seconds. Restart the agent to restore it to the default value.: MessagingTimeout: Timed out waiting for a reply to message ID 1ed3e021607e466f8b9b84cd3b05b188
2019-12-10 10:57:02.285 1838521 INFO eventlet.wsgi.server [-] 10.195.74.27,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200 len: 146 time: 0.7959940

2019-12-10 10:57:16.215 1838531 WARNING oslo_messaging._drivers.amqpdriver [-] Number of call queues is 21, greater than warning threshold: 20. There could be a leak. Increasing threshold to: 40

2019-12-10 10:57:17.339 1838539 WARNING oslo_messaging._drivers.amqpdriver [-] Number of call queues is 11, greater than warning threshold: 10. There could be a leak. Increasing threshold to: 20

2019-12-10 10:57:24.838 1838524 INFO eventlet.wsgi.server [-] 10.195.73.242,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200 len: 146 time: 0.6842020
2019-12-10 10:57:24.882 1838524 ERROR neutron.common.rpc [-] Timeout in RPC method get_ports. Waiting for 3 seconds before next attempt. If the server is not down, consider increasing the rpc_response_timeout option as Neutron server(s) may be overloaded and unable to respond quickly enough.: MessagingTimeout: Timed out waiting for a reply to message ID 2bb5faa3ec8d4f5b9d3bd3e2fe095f9e
2019-12-10 10:57:24.883 1838524 WARNING neutron.common.rpc [-] Increasing timeout for get_ports calls to 120 seconds. Restart the agent to restore it to the default value.: MessagingTimeout: Timed out waiting for a reply to message ID 2bb5faa3ec8d4f5b9d3bd3e2fe095f9e
2019-12-10 10:57:24.887 1838525 INFO eventlet.wsgi.server [-] 10.195.74.26,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200 len: 146 time: 0.9827850
2019-12-10 10:57:24.903 1838518 INFO eventlet.wsgi.server [-] 10.195.74.43,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200 len: 146 time: 3.5630379
2019-12-10 10:57:25.045 1838529 ERROR neutron.common.rpc [-] Timeout in RPC method get_ports. Waiting for 21 seconds before next attempt. If the server is not down, consider increasing the rpc_response_timeout option as Neutron server(s) may be overloaded and unable to respond quickly enough.: MessagingTimeout: Timed out waiting for a reply to message ID b38361bf9906482b8b24c5b534a6652b
2019-12-10 10:57:25.046 1838529 WARNING neutron.common.rpc [-] Increasing timeout for get_ports calls to 120 seconds. Restart the agent to restore it to the default value.: MessagingTimeout: Timed out waiting for a reply to message ID b38361bf9906482b8b24c5b534a6652b
2019-12-10 10:57:25.055 1838537 INFO eventlet.wsgi.server [-] 10.195.73.247,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200 len: 146 time: 0.7542410
2019-12-10 10:57:25.119 1838523 INFO eventlet.wsgi.server [-] 10.195.74.2,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200 len: 146 time: 0.7057869
2019-12-10 10:57:25.185 1838524 ERROR neutron.common.rpc [-] Timeout in RPC method get_ports. Waiting for 47 seconds before next attempt. If the server is not down, consider increasing the rpc_response_timeout option as Neutron server(s) may be overloaded and unable to respond quickly enough.: MessagingTimeout: Timed out waiting for a reply to message ID f1a268d937f94def97bd238916715744
2019-12-10 10:57:25.261 1838529 ERROR neutron.common.rpc [-] Timeout in RPC method get_ports. Waiting for 26 seconds before next attempt. If the server is not down, consider increasing the rpc_response_timeout option as Neutron server(s) may be overloaded and unable to respond quickly enough.: MessagingTimeout: Timed out waiting for a reply to message ID 93c31cf4f5d34bd1a5ba90165e89cb79
2019-12-10 10:57:25.284 1838536 INFO eventlet.wsgi.server [-] 10.195.73.207,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200 len: 146 time: 0.4315739
2019-12-10 10:57:25.319 1838520 ERROR neutron.common.rpc [-] Timeout in RPC method get_ports. Waiting for 50 seconds before next attempt. If the server is not down, consider increasing the rpc_response_timeout option as Neutron server(s) may be overloaded and unable to respond quickly enough.: MessagingTimeout: Timed out waiting for a reply to message ID 37c1b168536e4c70b522c330209b11ec
2019-12-10 10:57:25.319 1838520 WARNING neutron.common.rpc [-] Increasing timeout for get_ports calls to 120 seconds. Restart the agent to restore it to the default value.: MessagingTimeout: Timed out waiting for a reply to message ID 37c1b168536e4c70b522c330209b11ec
2019-12-10 10:57:25.374 1838530 ERROR neutron.common.rpc [-] Timeout in RPC method get_ports. Waiting for 30 seconds before next attempt. If the server is not down, consider increasing the rpc_response_timeout option as Neutron server(s) may be overloaded and unable to respond quickly enough.: MessagingTimeout: Timed out waiting for a reply to message ID fb837fc73c664209bfbada0fb32886ad
2019-12-10 10:57:25.375 1838530 WARNING neutron.common.rpc [-] Increasing timeout for get_ports calls to 120 seconds. Restart the agent to restore it to the default value.: MessagingTimeout: Timed out waiting for a reply to message ID fb837fc73c664209bfbada0fb32886ad
2019-12-10 10:57:25.388 1838526 INFO eventlet.wsgi.server [-] 10.195.65.7,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200 len: 146 time: 3.5798080
2019-12-10 10:57:25.446 1838520 INFO eventlet.wsgi.server [-] 10.195.74.104,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200 len: 146 time: 3.6868739
2019-12-10 10:57:25.448 1838528 INFO eventlet.wsgi.server [-] 10.195.74.202,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200 len: 146 time: 3.7513518
2019-12-10 10:57:25.452 1838519 WARNING oslo_messaging._drivers.amqpdriver [-] Number of call queues is 21, greater than warning threshold: 20. There could be a leak. Increasing threshold to: 40
2019-12-10 10:57:25.504 1838535 ERROR neutron.common.rpc [-] Timeout in RPC method get_ports. Waiting for 15 seconds before next attempt. If the server is not down, consider increasing the rpc_response_timeout option as Neutron server(s) may be overloaded and unable to respond quickly enough.: MessagingTimeout: Timed out waiting for a reply to message ID 7b677a7d40274b0ea22510dcf3865cf6
2019-12-10 10:57:25.505 1838535 WARNING neutron.common.rpc [-] Increasing timeout for get_ports calls to 120 seconds. Restart the agent to restore it to the default value.: MessagingTimeout: Timed out waiting for a reply to message ID 7b677a7d40274b0ea22510dcf3865cf6
2019-12-10 10:57:25.609 1838539 ERROR neutron.common.rpc [-] Timeout in RPC method get_ports. Waiting for 20 seconds before next attempt. If the server is not down, consider increasing the rpc_response_timeout option as Neutron server(s) may be overloaded and unable to respond quickly enough.: MessagingTimeout: Timed out waiting for a reply to message ID 378f11ce14334be38ffaa95ec3fc26f2
2019-12-10 10:57:25.610 1838539 WARNING neutron.common.rpc [-] Increasing timeout for get_ports calls to 120 seconds. Restart the agent to restore it to the default value.: MessagingTimeout: Timed out waiting for a reply to message ID 378f11ce14334be38ffaa95ec3fc26f2
2019-12-10 10:57:25.661 1838524 ERROR neutron.common.rpc [-] Timeout in RPC method get_ports. Waiting for 28 seconds before next attempt. If the server is not down, consider increasing the rpc_response_timeout option as Neutron server(s) may be overloaded and unable to respond quickly enough.: MessagingTimeout: Timed out waiting for a reply to message ID 0c911a0ac95f42209cfa8b265d4d5c3d
2019-12-10 10:57:25.787 1838525 INFO eventlet.wsgi.server [-] 10.195.74.86,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200 len: 146 time: 0.7191069
2019-12-10 10:57:25.831 1838522 INFO eventlet.wsgi.server [-] 10.195.64.185,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200 len: 146 time: 0.5980189
2019-12-10 10:57:25.837 1838532 ERROR neutron.common.rpc [-] Timeout in RPC method get_ports. Waiting for 51 seconds before next attempt. If the server is not down, consider increasing the rpc_response_timeout option as Neutron server(s) may be overloaded and unable to respond quickly enough.: MessagingTimeout: Timed out waiting for a reply to message ID 9a7cfd81ba714d2680aa223ba96798f0
2019-12-10 10:57:25.837 1838532 WARNING neutron.common.rpc [-] Increasing timeout for get_ports calls to 120 seconds. Restart the agent to restore it to the default value.: MessagingTimeout: Timed out waiting for a reply to message ID 9a7cfd81ba714d2680aa223ba96798f0
2019-12-10 10:57:25.903 1838536 ERROR neutron.common.rpc [-] Timeout in RPC method get_ports. Waiting for 28 seconds before next attempt. If the server is not down, consider increasing the rpc_response_timeout option as Neutron server(s) may be overloaded and unable to respond quickly enough.: MessagingTimeout: Timed out waiting for a reply to message ID da2628209cde4562bf47dc0bdfecbf1d
2019-12-10 10:57:25.904 1838536 WARNING neutron.common.rpc [-] Increasing timeout for get_ports calls to 120 seconds. Restart the agent to restore it to the default value.: MessagingTimeout: Timed out waiting for a reply to message ID da2628209cde4562bf47dc0bdfecbf1d
2019-12-10 10:57:25.914 1838521 INFO eventlet.wsgi.server [-] 10.195.74.44,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200 len: 146 time: 3.8841410
2019-12-10 10:57:25.936 1838524 INFO eventlet.wsgi.server [-] 10.195.73.231,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200 len: 146 time: 0.3305228

A minute or two after starting the server we get more errors. At this point VMs are unable to build. If I try to pull metadata from a VM get a 503 or 504 and nothing is logged in neutron-metadata-agent.log. Haproxy logs the 503/504 response.

albertb@<html><body><h1>503:~ $ curl -s http://169.254.169.254/2009-04-04/meta-data/hostname
<html><body><h1>503 Service Unavailable</h1>
No server is available to handle this request.
</body></html>

Now the log is almost all errors:

2019-12-10 10:57:27.666 1838530 INFO eventlet.wsgi.server [-] 10.195.73.174,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200 len: 146 time: 3.7101889
2019-12-10 10:57:27.719 1838537 INFO eventlet.wsgi.server [-] 10.195.65.6,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200 len: 146 time: 0.3497119
2019-12-10 10:57:27.720 1838525 ERROR neutron.common.rpc [-] Timeout in RPC method get_ports. Waiting for 60 seconds before next attempt. If the server is not down, consider increasing the rpc_response_timeout option as Neutron server(s) may be overloaded and unable to respond quickly enough.: MessagingTimeout: Timed out waiting for a reply to message ID 138877a7326e40f38de23b05fb97127a
2019-12-10 10:57:27.720 1838525 WARNING neutron.common.rpc [-] Increasing timeout for get_ports calls to 120 seconds. Restart the agent to restore it to the default value.: MessagingTimeout: Timed out waiting for a reply to message ID 138877a7326e40f38de23b05fb97127a
2019-12-10 10:57:27.741 1838523 INFO eventlet.wsgi.server [-] 10.195.74.86,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200 len: 146 time: 4.7329929
2019-12-10 10:57:27.820 1838525 INFO eventlet.wsgi.server [-] 10.195.73.206,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200 len: 146 time: 1.4146030
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent [-] Unexpected error.: MessagingTimeout: Timed out waiting for a reply to message ID 2bb5faa3ec8d4f5b9d3bd3e2fe095f9e
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent Traceback (most recent call last):
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent File "/usr/lib/python2.7/dist-packages/neutron/agent/metadata/agent.py", line 89, in __call__
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent instance_id, tenant_id = self._get_instance_and_tenant_id(req)
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent File "/usr/lib/python2.7/dist-packages/neutron/agent/metadata/agent.py", line 162, in _get_instance_and_tenant_id
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent ports = self._get_ports(remote_address, network_id, router_id)
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent File "/usr/lib/python2.7/dist-packages/neutron/agent/metadata/agent.py", line 155, in _get_ports
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent return self._get_ports_for_remote_address(remote_address, networks)
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent File "/usr/lib/python2.7/dist-packages/neutron/common/cache_utils.py", line 116, in __call__
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent return self.func(target_self, *args, **kwargs)
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent File "/usr/lib/python2.7/dist-packages/neutron/agent/metadata/agent.py", line 137, in _get_ports_for_remote_address
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent ip_address=remote_address)
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent File "/usr/lib/python2.7/dist-packages/neutron/agent/metadata/agent.py", line 106, in _get_ports_from_server
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent return self.plugin_rpc.get_ports(self.context, filters)
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent File "/usr/lib/python2.7/dist-packages/neutron/agent/metadata/agent.py", line 72, in get_ports
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent return cctxt.call(context, 'get_ports', filters=filters)
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent File "/usr/lib/python2.7/dist-packages/neutron/common/rpc.py", line 173, in call
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent time.sleep(wait)
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent File "/usr/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent self.force_reraise()
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent File "/usr/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent six.reraise(self.type_, self.value, self.tb)
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent File "/usr/lib/python2.7/dist-packages/neutron/common/rpc.py", line 150, in call
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent return self._original_context.call(ctxt, method, **kwargs)
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent File "/usr/lib/python2.7/dist-packages/oslo_messaging/rpc/client.py", line 179, in call
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent retry=self.retry)
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent File "/usr/lib/python2.7/dist-packages/oslo_messaging/transport.py", line 133, in _send
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent retry=retry)
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 584, in send
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent call_monitor_timeout, retry=retry)
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 573, in _send
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent call_monitor_timeout)
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 459, in wait
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent message = self.waiters.get(msg_id, timeout=timeout)
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 336, in get
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent 'to message ID %s' % msg_id)
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent MessagingTimeout: Timed out waiting for a reply to message ID 2bb5faa3ec8d4f5b9d3bd3e2fe095f9e
2019-12-10 10:57:27.824 1838524 ERROR neutron.agent.metadata.agent
2019-12-10 10:57:27.828 1838524 INFO eventlet.wsgi.server [-] Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/eventlet/wsgi.py", line 521, in handle_one_response
    write(b''.join(towrite))
  File "/usr/lib/python2.7/dist-packages/eventlet/wsgi.py", line 462, in write
    wfile.flush()
  File "/usr/lib/python2.7/socket.py", line 307, in flush
    self._sock.sendall(view[write_offset:write_offset+buffer_size])
  File "/usr/lib/python2.7/dist-packages/eventlet/greenio/base.py", line 390, in sendall
    tail = self.send(data, flags)
  File "/usr/lib/python2.7/dist-packages/eventlet/greenio/base.py", line 384, in send
    return self._send_loop(self.fd.send, data, flags)
  File "/usr/lib/python2.7/dist-packages/eventlet/greenio/base.py", line 371, in _send_loop
    return send_method(data, *args)
error: [Errno 32] Broken pipe

2019-12-10 10:57:27.828 1838524 INFO eventlet.wsgi.server [-] 10.195.73.248,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 500 len: 0 time: 63.0060959
2019-12-10 10:57:27.873 1838528 ERROR neutron.common.rpc [-] Timeout in RPC method get_ports. Waiting for 41 seconds before next attempt. If the server is not down, consider increasing the rpc_response_timeout option as Neutron server(s) may be overloaded and unable to respond quickly enough.: MessagingTimeout: Timed out waiting for a reply to message ID 7d73358e2fe841e4a4b818395e2e5b2d
2019-12-10 10:57:27.877 1838524 INFO eventlet.wsgi.server [-] 10.195.73.238,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200 len: 146 time: 4.4559531
2019-12-10 10:57:27.921 1838538 ERROR neutron.common.rpc [-] Timeout in RPC method get_ports. Waiting for 6 seconds before next attempt. If the server is not down, consider increasing the rpc_response_timeout option as Neutron server(s) may be overloaded and unable to respond quickly enough.: MessagingTimeout: Timed out waiting for a reply to message ID 297db0c16653413cabc868027f9e6abb
2019-12-10 10:57:27.921 1838538 WARNING neutron.common.rpc [-] Increasing timeout for get_ports calls to 120 seconds. Restart the agent to restore it to the default value.: MessagingTimeout: Timed out waiting for a reply to message ID 297db0c16653413cabc868027f9e6abb
2019-12-10 10:57:27.967 1838520 INFO eventlet.wsgi.server [-] 10.195.74.29,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200 len: 146 time: 0.4040241
2019-12-10 10:57:28.006 1838517 INFO eventlet.wsgi.server [-] 10.195.74.202,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200 len: 146 time: 3.6681471
2019-12-10 10:57:28.026 1838522 INFO eventlet.wsgi.server [-] 10.195.74.202,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200 len: 146 time: 0.3529530
2019-12-10 10:57:28.058 1838519 INFO eventlet.wsgi.server [-] 10.195.74.121,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200 len: 146 time: 3.5390451

To reproduce this issue:

Build openstack cluster on Rocky and add 200 computes. 3 controllers with 48 CPU Intel(R) Xeon(R) Gold 5118 CPU @ 2.30GHz and 92G RAM.

This bug seems severe to us. It is ruining our production cluster and we cannot build VMs.

Tags:

Revision history for this message

Albert Braden (ozzzo) wrote on 2019-12-10:

This looks similar to bug 1853071 so we installed the patch but it didn't seem to make a difference:

https://bugs.launchpad.net/neutron/+bug/1853071

https://review.opendev.org/#/c/697405/

summary:	- roken pipe erros cause neutron metadata agent to fail + broken pipe erros cause neutron metadata agent to fail
summary:	- broken pipe erros cause neutron metadata agent to fail + broken pipe errors cause neutron metadata agent to fail

Revision history for this message

Rodolfo Alonso (rodolfo-alonso-hernandez) wrote on 2019-12-11:

Hello Albert:

I don't think this is related to DB locks but to the MQ you are using. Did you check the status of the MQ? What is the status of the Neutron server? Do you see any error in the server logs?

If you are running RabbitMQ, please use https://www.rabbitmq.com/cli.html to check the status of the MQ.

Regards.

Revision history for this message

Slawek Kaplonski (slaweq) wrote on 2019-12-11:

Hi,

Can You provide neutron-server logs from the same time? Errors like "Timeout in RPC method get_ports" can indicate that there was some issue on neutron-server's side or in rabbitmq itself.
So please also check rabbitmq status.
Another thing to check is status of Your database and overall controllers/db nodes load as another potential reason of this can be simple overloaded control plane.

I'm marking this for now as incomplete. Please switch it to new again when You will provide additional data.

Changed in neutron:
status:	New → Incomplete

Revision history for this message

Albert Braden (ozzzo) wrote on 2019-12-11:

Download full text (21.3 KiB)

neutron-server logs show a few warnings while the server starts but no errors:

2019-12-10 10:55:59.961 1838396 INFO neutron.api.extensions [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Extension router-service-type not supported by any of loaded plugins
2019-12-10 10:55:59.961 1838396 INFO neutron.api.extensions [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Loaded extension: port-security-groups-filtering
2019-12-10 10:55:59.962 1838396 WARNING neutron.api.extensions [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Did not find expected name "Security_groups_port_filtering_lib" in /usr/lib/python2.7/dist-packages/neutron/extensions/security_groups_port_filtering_lib.py
2019-12-10 10:55:59.964 1838396 INFO neutron.api.extensions [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Loaded extension: security-group
2019-12-10 10:55:59.965 1838396 INFO neutron.api.extensions [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Extension segment not supported by any of loaded plugins
2019-12-10 10:55:59.966 1838396 INFO neutron.api.extensions [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Extension segments-peer-subnet-host-routes not supported by any of loaded plugins
2019-12-10 10:55:59.966 1838396 INFO neutron.api.extensions [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Loaded extension: service-type
2019-12-10 10:55:59.967 1838396 INFO neutron.api.extensions [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Loaded extension: sorting
2019-12-10 10:55:59.967 1838396 INFO neutron.api.extensions [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Extension standard-attr-segment not supported by any of loaded plugins
2019-12-10 10:55:59.968 1838396 INFO neutron.api.extensions [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Loaded extension: standard-attr-description
2019-12-10 10:55:59.968 1838396 WARNING neutron.api.extensions [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Did not find expected name "Stdattrs_common" in /usr/lib/python2.7/dist-packages/neutron/extensions/stdattrs_common.py
2019-12-10 10:55:59.969 1838396 INFO neutron.api.extensions [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Extension subnet-segmentid-writable not supported by any of loaded plugins
2019-12-10 10:55:59.969 1838396 INFO neutron.api.extensions [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Loaded extension: subnet-service-types
2019-12-10 10:55:59.970 1838396 INFO neutron.api.extensions [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Loaded extension: subnet_allocation
2019-12-10 10:55:59.971 1838396 INFO neutron.api.extensions [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Loaded extension: standard-attr-tag
2019-12-10 10:55:59.971 1838396 INFO neutron.api.extensions [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Loaded extension: standard-attr-timestamp
2019-12-10 10:55:59.972 1838396 INFO neutron.api.extensions [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Extension trunk not supported by any of loaded plugins
2019-12-10 10:55:59.972 1838396 INFO neutron.api.extensions [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Extension trunk-details not supported by any of loaded plugins
2019-12-10 10:55:59.973 1838396 INFO neutron.api.extensions [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Extension vlan-transparent not supported by any of loaded plugins
2019-12-10 10:55:59.974 1838396 INFO neutron.quota.resource_registry [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Creating instance of TrackedResource for resource:subnet
2019-12-10 10:55:59.974 1838396 INFO neutron.quota.resource_registry [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Creating instance of TrackedResource for resource:subnetpool
2019-12-10 10:55:59.975 1838396 INFO neutron.quota.resource_registry [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Creating instance of TrackedResource for resource:network
2019-12-10 10:55:59.975 1838396 INFO neutron.quota.resource_registry [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Creating instance of TrackedResource for resource:port
2019-12-10 10:55:59.976 1838396 INFO neutron.quota.resource_registry [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Creating instance of TrackedResource for resource:security_group
2019-12-10 10:55:59.977 1838396 INFO neutron.quota.resource_registry [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Creating instance of TrackedResource for resource:security_group_rule
2019-12-10 10:55:59.978 1838396 INFO neutron.quota.resource_registry [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Creating instance of CountableResource for resource:rbac_policy
2019-12-10 10:55:59.978 1838396 INFO neutron.quota.resource_registry [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Creating instance of TrackedResource for resource:router
2019-12-10 10:55:59.979 1838396 INFO neutron.quota.resource_registry [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Creating instance of TrackedResource for resource:floatingip
2019-12-10 10:55:59.981 1838396 INFO neutron.quota.resource_registry [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Creating instance of TrackedResource for resource:security_group
2019-12-10 10:55:59.981 1838396 WARNING neutron.quota.resource_registry [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] security_group is already registered
2019-12-10 10:55:59.981 1838396 INFO neutron.quota.resource_registry [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Creating instance of TrackedResource for resource:security_group_rule
2019-12-10 10:55:59.981 1838396 WARNING neutron.quota.resource_registry [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] security_group_rule is already registered
2019-12-10 10:55:59.982 1838396 INFO neutron.quota.resource_registry [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Creating instance of CountableResource for resource:rbac_policy
2019-12-10 10:55:59.982 1838396 WARNING neutron.quota.resource_registry [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] rbac_policy is already registered
2019-12-10 10:55:59.982 1838396 INFO neutron.quota.resource_registry [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Creating instance of TrackedResource for resource:router
2019-12-10 10:55:59.982 1838396 WARNING neutron.quota.resource_registry [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] router is already registered
2019-12-10 10:55:59.983 1838396 INFO neutron.quota.resource_registry [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Creating instance of TrackedResource for resource:floatingip
2019-12-10 10:55:59.983 1838396 WARNING neutron.quota.resource_registry [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] floatingip is already registered
2019-12-10 10:56:00.010 1838396 WARNING keystonemiddleware._common.config [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] The option "__file__" in conf is not known to auth_token
2019-12-10 10:56:00.011 1838396 WARNING keystonemiddleware._common.config [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] The option "here" in conf is not known to auth_token
2019-12-10 10:56:00.012 1838396 WARNING keystonemiddleware.auth_token [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] AuthToken middleware is set with keystone_authtoken.service_token_roles_required set to False. This is backwards compatible but deprecated behaviour. Please set this to True.
2019-12-10 10:56:00.033 1838396 INFO oslo_service.service [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Starting 48 workers
2019-12-10 10:56:00.047 1838430 INFO neutron.wsgi [-] (1838430) wsgi starting up on http://0.0.0.0:9696
2019-12-10 10:56:00.050 1838431 INFO neutron.wsgi [-] (1838431) wsgi starting up on http://0.0.0.0:9696

After it finishes starting there are no errors:
2019-12-10 10:56:00.163 1838481 INFO neutron.wsgi [-] (1838481) wsgi starting up on http://0.0.0.0:9696
2019-12-10 10:56:00.165 1838482 INFO neutron.wsgi [-] (1838482) wsgi starting up on http://0.0.0.0:9696
2019-12-10 10:56:00.168 1838396 INFO neutron.service [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Neutron service started, listening on 0.0.0.0:9696
2019-12-10 10:56:00.168 1838483 INFO neutron.wsgi [-] (1838483) wsgi starting up on http://0.0.0.0:9696
2019-12-10 10:56:00.171 1838396 INFO oslo_service.service [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Starting 1 workers
2019-12-10 10:56:00.173 1838484 INFO neutron.wsgi [-] (1838484) wsgi starting up on http://0.0.0.0:9696
2019-12-10 10:56:00.177 1838396 INFO oslo_service.service [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Starting 1 workers
2019-12-10 10:56:00.184 1838396 INFO oslo_service.service [req-1ec38ea9-9081-47d7-be2b-22f076080cab - - - - -] Starting 1 workers
2019-12-10 10:56:00.460 1838430 INFO neutron.wsgi [req-f0f1e9f3-3cd9-46e2-a5ec-1519ee4f4060 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/ports?tenant_id=0b591e0864d04e6b8b6afa18a5a4a638&device_id=f3c748d5-74d2-4358-83bd-cf6659add5f4 HTTP/1.1" status: 200  len: 1263 time: 0.4105549
2019-12-10 10:56:00.528 1838472 INFO neutron.wsgi [req-3439cfb8-148e-44bf-8332-80127499e6f9 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/ports?tenant_id=3a31db4edfe5497c86263a47ef9b01f0&device_id=a4e4278c-36f3-48b9-bbdf-19bcffbe00cf HTTP/1.1" status: 200  len: 1249 time: 0.3883860
2019-12-10 10:56:00.550 1838430 INFO neutron.wsgi [req-7c526b9e-b160-42a2-a513-9d35ddaae662 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/networks?id=569e2c42-3935-48e9-ae41-074650e57b2b HTTP/1.1" status: 200  len: 916 time: 0.0849628
2019-12-10 10:56:00.597 1838430 INFO neutron.wsgi [req-82f8d604-c529-436d-8f60-ce93d252cea5 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/floatingips?fixed_ip_address=10.195.74.187&port_id=66905856-ec22-452c-ab1f-ed07ecf5d1c6 HTTP/1.1" status: 200  len: 217 time: 0.0425282
2019-12-10 10:56:00.616 1838472 INFO neutron.wsgi [req-ce02c373-7b29-4cf1-a918-c14b54a7def6 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/networks?id=40c76f56-ff7d-4a15-9dc6-10b65d74801b HTTP/1.1" status: 200  len: 916 time: 0.0841739

...

2019-12-10 10:56:05.291 1838434 INFO neutron.wsgi [req-ee9c0a8a-c75d-4c34-908e-d6284f794736 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/floatingips?fixed_ip_address=10.195.74.75&port_id=1d2aaee5-4ed5-4d3a-bafe-dfe3da5d09e1 HTTP/1.1" status: 200  len: 217 time: 0.0501220
2019-12-10 10:56:05.325 1838434 INFO neutron.wsgi [req-82aa0240-0cb6-4c24-a7e3-4d9bf24f3e5d 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/subnets?id=fb6475e1-4494-450b-b748-088da0ae6c1c HTTP/1.1" status: 200  len: 846 time: 0.0302262
2019-12-10 10:56:05.372 1838434 INFO neutron.wsgi [req-3d21ab23-51e5-48c4-a537-593c641c111b 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/ports?network_id=569e2c42-3935-48e9-ae41-074650e57b2b&device_owner=network%3Adhcp HTTP/1.1" status: 200  len: 3262 time: 0.0420940
2019-12-10 10:56:05.450 1838434 INFO neutron.wsgi [req-b99c0ad2-33bd-4f88-95c9-f7bc2da7d7d5 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/networks/569e2c42-3935-48e9-ae41-074650e57b2b?fields=segments HTTP/1.1" status: 200  len: 212 time: 0.0731840
2019-12-10 10:56:05.519 1838434 INFO neutron.wsgi [req-bba98f47-61d7-4a3d-9885-f2a2894abf9a 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/networks/569e2c42-3935-48e9-ae41-074650e57b2b?fields=provider%3Aphysical_network&fields=provider%3Anetwork_type HTTP/1.1" status: 200  len: 281 time: 0.0654719
2019-12-10 10:56:05.580 1838433 INFO neutron.wsgi [req-9b05cf43-64f3-4ceb-b390-3e9f3268cfca 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/ports?tenant_id=0b591e0864d04e6b8b6afa18a5a4a638&device_id=a04b2f94-f435-49c1-ab0c-65cba7aeeade HTTP/1.1" status: 200  len: 1255 time: 0.3424220
2019-12-10 10:56:05.689 1838433 INFO neutron.wsgi [req-c8bbe722-0728-470b-ba97-4e36171920a0 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/networks?id=569e2c42-3935-48e9-ae41-074650e57b2b HTTP/1.1" status: 200  len: 916 time: 0.1062999
2019-12-10 10:56:05.736 1838463 INFO neutron.wsgi [-] 10.195.54.1 "OPTIONS / HTTP/1.0" status: 200  len: 248 time: 0.0008900
2019-12-10 10:56:05.737 1838433 INFO neutron.wsgi [req-acda5025-fac0-4ea1-8a9d-82ccab11a258 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/floatingips?fixed_ip_address=10.195.72.77&port_id=27d12ef4-d561-43f0-af88-710c99dbedbf HTTP/1.1" status: 200  len: 217 time: 0.0444231
2019-12-10 10:56:05.772 1838433 INFO neutron.wsgi [req-4a1a5ce0-7d26-42de-abd5-6423647f337a 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/subnets?id=fb6475e1-4494-450b-b748-088da0ae6c1c HTTP/1.1" status: 200  len: 846 time: 0.0324309
2019-12-10 10:56:05.825 1838433 INFO neutron.wsgi [req-97cec855-d250-43b7-af8f-95aec92acda6 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/ports?network_id=569e2c42-3935-48e9-ae41-074650e57b2b&device_owner=network%3Adhcp HTTP/1.1" status: 200  len: 3262 time: 0.0508130
2019-12-10 10:56:05.905 1838433 INFO neutron.wsgi [req-f57d17cd-a7ff-418f-a3fe-2134e4d44b4d 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/networks/569e2c42-3935-48e9-ae41-074650e57b2b?fields=segments HTTP/1.1" status: 200  len: 212 time: 0.0755479
2019-12-10 10:56:05.995 1838433 INFO neutron.wsgi [req-aa5b99ea-1f64-4eb0-8b99-7a2f6526e0ac 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/networks/569e2c42-3935-48e9-ae41-074650e57b2b?fields=provider%3Aphysical_network&fields=provider%3Anetwork_type HTTP/1.1" status: 200  len: 281 time: 0.0878661
2019-12-10 10:56:06.147 1838477 INFO neutron.wsgi [req-218ab442-148d-43db-8e38-066f2c546562 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/ports?tenant_id=0b591e0864d04e6b8b6afa18a5a4a638&device_id=177cd4ee-6aea-4d22-85f8-7e47e0fb925f HTTP/1.1" status: 200  len: 1255 time: 0.5179400
2019-12-10 10:56:06.227 1838477 INFO neutron.wsgi [req-158cf94a-6be5-4ba2-b30d-8c19c7ce07f7 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/networks?id=569e2c42-3935-48e9-ae41-074650e57b2b HTTP/1.1" status: 200  len: 916 time: 0.0745220
2019-12-10 10:56:06.272 1838477 INFO neutron.wsgi [req-72e02a20-4db4-47ae-81f9-461220179722 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/floatingips?fixed_ip_address=10.195.74.55&port_id=ce4cccc0-5e55-4e39-9db8-ee8d04846a0e HTTP/1.1" status: 200  len: 217 time: 0.0413980
2019-12-10 10:56:06.314 1838477 INFO neutron.wsgi [req-b66a34f9-7ccd-4b72-acc5-a02ce9487e1b 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/subnets?id=fb6475e1-4494-450b-b748-088da0ae6c1c HTTP/1.1" status: 200  len: 846 time: 0.0374980

...

2019-12-10 10:56:16.157 1838444 INFO neutron.wsgi [req-e5e4ded6-41e6-442e-b309-f70b2cf61dc7 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/subnets?id=fb6475e1-4494-450b-b748-088da0ae6c1c HTTP/1.1" status: 200  len: 846 time: 0.0307870
2019-12-10 10:56:16.160 1838479 INFO neutron.wsgi [req-33a66416-1ec6-49c3-b2cf-395187d4a61e 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/ports?tenant_id=0b591e0864d04e6b8b6afa18a5a4a638&device_id=11597f69-42bd-4fb7-9f7f-9d8327f9f01b HTTP/1.1" status: 200  len: 1255 time: 0.3562229
2019-12-10 10:56:16.202 1838444 INFO neutron.wsgi [req-ebea5cd3-6730-4a94-95f4-908c66f691db 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/ports?network_id=569e2c42-3935-48e9-ae41-074650e57b2b&device_owner=network%3Adhcp HTTP/1.1" status: 200  len: 3262 time: 0.0405960
2019-12-10 10:56:16.260 1838479 INFO neutron.wsgi [req-560a9aa9-4dce-4911-be32-4b5a45b5611d 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/networks?id=569e2c42-3935-48e9-ae41-074650e57b2b HTTP/1.1" status: 200  len: 916 time: 0.0946450
2019-12-10 10:56:16.271 1838444 INFO neutron.wsgi [req-42b2d1b0-4291-40ab-aff6-9d7c7c95c779 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/networks/569e2c42-3935-48e9-ae41-074650e57b2b?fields=segments HTTP/1.1" status: 200  len: 212 time: 0.0643811
2019-12-10 10:56:16.294 1838442 INFO neutron.wsgi [req-b69e6e78-6815-4add-9dbc-f5fde5ba35e7 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/ports?tenant_id=0b591e0864d04e6b8b6afa18a5a4a638&device_id=b8cae2d8-f547-4323-bf90-a5017c71240f HTTP/1.1" status: 200  len: 1264 time: 0.3781641
2019-12-10 10:56:16.296 1838431 INFO neutron.wsgi [req-47b823da-0761-4a57-a501-ffac1556b35f 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/ports?tenant_id=0b591e0864d04e6b8b6afa18a5a4a638&device_id=dae0dc20-c2c8-4e03-b6fb-947fd82e16c0 HTTP/1.1" status: 200  len: 2230 time: 0.0576649
2019-12-10 10:56:16.330 1838479 INFO neutron.wsgi [req-010bd04e-0e6f-48d1-b941-36ddbbb8a15a 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/floatingips?fixed_ip_address=10.195.75.21&port_id=28670a6a-b5a3-4678-9672-872d38f94939 HTTP/1.1" status: 200  len: 217 time: 0.0652039
2019-12-10 10:56:16.340 1838444 INFO neutron.wsgi [req-c02eed6e-ab5b-4318-a641-b1e498d1b71a 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/networks/569e2c42-3935-48e9-ae41-074650e57b2b?fields=provider%3Aphysical_network&fields=provider%3Anetwork_type HTTP/1.1" status: 200  len: 281 time: 0.0641119
2019-12-10 10:56:16.366 1838479 INFO neutron.wsgi [req-be8755e7-2735-40db-bee5-3d1961682926 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/subnets?id=fb6475e1-4494-450b-b748-088da0ae6c1c HTTP/1.1" status: 200  len: 846 time: 0.0317590
2019-12-10 10:56:16.370 1838431 INFO neutron.wsgi [req-244f4179-efbb-48ad-9776-0e4fb699a6c5 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/networks?id=569e2c42-3935-48e9-ae41-074650e57b2b HTTP/1.1" status: 200  len: 916 time: 0.0689850
2019-12-10 10:56:16.382 1838442 INFO neutron.wsgi [req-abb3c202-827b-421a-883b-7720e3a40a8b 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/networks?id=569e2c42-3935-48e9-ae41-074650e57b2b HTTP/1.1" status: 200  len: 916 time: 0.0832999
2019-12-10 10:56:16.414 1838479 INFO neutron.wsgi [req-0762ee4c-98f1-4523-8287-e83cc8c667f5 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/ports?network_id=569e2c42-3935-48e9-ae41-074650e57b2b&device_owner=network%3Adhcp HTTP/1.1" status: 200  len: 3262 time: 0.0435240
2019-12-10 10:56:16.416 1838431 INFO neutron.wsgi [req-0ae5590e-6665-4f29-86dc-4b1258e74fe9 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/floatingips?fixed_ip_address=10.195.72.145&port_id=3964e9ff-e4d3-46dd-8de9-68700c981300 HTTP/1.1" status: 200  len: 217 time: 0.0424709
2019-12-10 10:56:16.429 1838442 INFO neutron.wsgi [req-4cb18208-bea8-44c6-8d1b-b4e610236695 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/floatingips?fixed_ip_address=10.195.73.32&port_id=6346c478-3901-4ab8-a49d-6a461a29541c HTTP/1.1" status: 200  len: 217 time: 0.0425968
2019-12-10 10:56:16.454 1838431 INFO neutron.wsgi [req-453143b2-e254-4088-be07-1860ccfe6f23 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/subnets?id=fb6475e1-4494-450b-b748-088da0ae6c1c HTTP/1.1" status: 200  len: 846 time: 0.0341568
2019-12-10 10:56:16.464 1838442 INFO neutron.wsgi [req-5a50265a-718e-416b-b37b-4a24306a448f 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/subnets?id=fb6475e1-4494-450b-b748-088da0ae6c1c HTTP/1.1" status: 200  len: 846 time: 0.0308180
2019-12-10 10:56:16.489 1838479 INFO neutron.wsgi [req-c1be475d-4345-41f1-9a98-85c9440c33a2 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/networks/569e2c42-3935-48e9-ae41-074650e57b2b?fields=segments HTTP/1.1" status: 200  len: 212 time: 0.0690458
2019-12-10 10:56:16.497 1838431 INFO neutron.wsgi [req-902de633-c2a4-4707-a130-1f47964defcc 542c93b042bd4f98af6fbe95952d47c0 490c190a23e84f07846d66f2906516ad - default default] 10.195.54.1 "GET /v2.0/ports?network_id=569e2c42-3935-48e9-ae41-074650e57b2b&device_owner=network%3Adhcp HTTP/1.1" status: 200  len: 3262 time: 0.0389330

Revision history for this message

Albert Braden (ozzzo) wrote on 2019-12-11:

Download full text (13.2 KiB)

I also see some RPC errors in neutron-linuxbridge-agent.log:

2019-12-10 10:57:02.562 1838419 INFO neutron.agent.securitygroups_rpc [req-4e5730f4-0207-4662-a738-eb4d13031eb4 5b288691527245bda715ab7744a193e9 deea2d8541f741eda6fb0d242d16bb23 - - -] Security group member updated [u'7272e9f5-d2fa-4b90-9ab3-aa850f0a9676']
2019-12-10 10:57:02.641 1838419 ERROR neutron.common.rpc [req-1d88bbfd-ff27-4760-aba5-550b02849e6b - - - - -] Timeout in RPC method security_group_info_for_devices. Waiting for 27 seconds before next attempt. If the server is not down, consider increasing the rpc_response_timeout option as Neutron server(s) may be overloaded and unable to respond quickly enough.: MessagingTimeout: Timed out waiting for a reply to message ID e790ca44021d42a093bcb5f2d910fb78
2019-12-10 10:57:02.641 1838419 WARNING neutron.common.rpc [req-1d88bbfd-ff27-4760-aba5-550b02849e6b - - - - -] Increasing timeout for security_group_info_for_devices calls to 120 seconds. Restart the agent to restore it to the default value.: MessagingTimeout: Timed out waiting for a reply to message ID e790ca44021d42a093bcb5f2d910fb78
2019-12-10 10:57:03.000 1838419 INFO neutron.agent.securitygroups_rpc [req-aae08091-6a85-4c7b-a163-96d0f4addb4f 5b288691527245bda715ab7744a193e9 deea2d8541f741eda6fb0d242d16bb23 - - -] Security group member updated [u'7272e9f5-d2fa-4b90-9ab3-aa850f0a9676']

I also see some RPC errors in neutron-linuxbridge-agent.log:

2019-12-10 10:57:15.026 1838419 INFO neutron.agent.securitygroups_rpc [req-32e97ef9-379c-443c-9fef-3dd495f338ef 5b288691527245bda715ab7744a193e9 deea2d8541f741eda6fb0d242d16bb23 - - -] Security group member updated [u'7272e9f5-d2fa-4b90-9ab3-aa850f0a9676']
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent [req-1d88bbfd-ff27-4760-aba5-550b02849e6b - - - - -] Error in agent loop. Devices info: {'current': set(['tapf365fa90-08', 'tapb947ec93-64', 'tap704b42f4-6a', 'tapf380ae4c-c2']), 'timestamps': {'tapb947ec93-64': 9, 'tap704b42f4-6a': 10, 'tapf365fa90-08': 11, 'tapf380ae4c-c2': 12}, 'removed': set([]), 'added': set(['tapf365fa90-08', 'tapb947ec93-64', 'tap704b42f4-6a', 'tapf380ae4c-c2']), 'updated': set([])}: MessagingTimeout: Timed out waiting for a reply to message ID e790ca44021d42a093bcb5f2d910fb78
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent Traceback (most recent call last):
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/lib/python2.7/dist-packages/neutron/plugins/ml2/drivers/agent/_common_agent.py", line 458, in daemon_loop
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent     sync = self.process_network_devices(device_info)
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/lib/python2.7/dist-packages/osprofiler/profiler.py", line 158, in wrapper
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent     result = f(*args, **kwargs)
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/lib/python2.7/dist-packages/neutron/plugins/ml2/drivers/agent/_common_agent.py", line 202, in process_network_devices
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent     device_info.get('updated'))
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/lib/python2.7/dist-packages/neutron/agent/securitygroups_rpc.py", line 256, in setup_port_filters
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent     self.prepare_devices_filter(new_devices)
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/lib/python2.7/dist-packages/neutron/agent/securitygroups_rpc.py", line 123, in decorated_function
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent     *args, **kwargs)
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/lib/python2.7/dist-packages/neutron/agent/securitygroups_rpc.py", line 131, in prepare_devices_filter
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent     self._apply_port_filter(device_ids)
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/lib/python2.7/dist-packages/neutron/agent/securitygroups_rpc.py", line 135, in _apply_port_filter
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent     if self.use_enhanced_rpc:
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/lib/python2.7/dist-packages/neutron/agent/securitygroups_rpc.py", line 98, in use_enhanced_rpc
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent     self._check_enhanced_rpc_is_supported_by_server())
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/lib/python2.7/dist-packages/neutron/agent/securitygroups_rpc.py", line 104, in _check_enhanced_rpc_is_supported_by_server
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent     self.context, devices=[])
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/lib/python2.7/dist-packages/neutron/api/rpc/handlers/securitygroups_rpc.py", line 60, in security_group_info_for_devices
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent     devices=devices)
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/lib/python2.7/dist-packages/neutron/common/rpc.py", line 173, in call
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent     time.sleep(wait)
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent     self.force_reraise()
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent     six.reraise(self.type_, self.value, self.tb)
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/lib/python2.7/dist-packages/neutron/common/rpc.py", line 150, in call
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent     return self._original_context.call(ctxt, method, **kwargs)
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/lib/python2.7/dist-packages/oslo_messaging/rpc/client.py", line 179, in call
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent     retry=self.retry)
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/lib/python2.7/dist-packages/oslo_messaging/transport.py", line 133, in _send
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent     retry=retry)
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 584, in send
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent     call_monitor_timeout, retry=retry)
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 573, in _send
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent     call_monitor_timeout)
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 459, in wait
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent     message = self.waiters.get(msg_id, timeout=timeout)
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent   File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 336, in get
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent     'to message ID %s' % msg_id)
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent MessagingTimeout: Timed out waiting for a reply to message ID e790ca44021d42a093bcb5f2d910fb78
2019-12-10 10:57:30.119 1838419 ERROR neutron.plugins.ml2.drivers.agent._common_agent
2019-12-10 10:57:30.123 1838419 INFO neutron.plugins.ml2.drivers.agent._common_agent [req-1d88bbfd-ff27-4760-aba5-550b02849e6b - - - - -] Linux bridge agent Agent out of sync with plugin!
2019-12-10 10:57:30.123 1838419 INFO neutron.agent.securitygroups_rpc [req-1d88bbfd-ff27-4760-aba5-550b02849e6b - - - - -] Preparing filters for devices set(['tapf365fa90-08', 'tapb947ec93-64', 'tap704b42f4-6a', 'tapf380ae4c-c2'])
2019-12-10 10:57:35.786 1838419 INFO neutron.plugins.ml2.drivers.agent._common_agent [req-1d88bbfd-ff27-4760-aba5-550b02849e6b - - - - -] Port tap704b42f4-6a updated. Details: {u'profile': {}, u'network_qos_policy_id': None, u'qos_policy_id': None, u'allowed_address_pairs': [], u'admin_state_up': True, u'network_id': u'40c76f56-ff7d-4a15-9dc6-10b65d74801b', u'segmentation_id': 509, u'mtu': 1500, u'device_owner': u'network:dhcp', u'physical_network': u'physnet1', u'mac_address': u'fa:16:3e:6a:6a:8c', u'device': u'tap704b42f4-6a', u'port_security_enabled': False, u'port_id': u'704b42f4-6afc-4c37-b55f-c4759ef8b796', u'fixed_ips': [{u'subnet_id': u'e40ff997-1998-4f1b-be0d-9f20ff8a9b71', u'ip_address': u'10.195.64.12'}], u'network_type': u'vlan'}
2019-12-10 10:57:35.857 1838419 INFO neutron.plugins.ml2.drivers.linuxbridge.agent.arp_protect [req-1d88bbfd-ff27-4760-aba5-550b02849e6b - - - - -] Skipping ARP spoofing rules for port 'tap704b42f4-6a' because it has port security disabled
2019-12-10 10:58:36.086 1838419 ERROR neutron.common.rpc [req-1d88bbfd-ff27-4760-aba5-550b02849e6b - - - - -] Timeout in RPC method update_device_up. Waiting for 40 seconds before next attempt. If the server is not down, consider increasing the rpc_response_timeout option as Neutron server(s) may be overloaded and unable to respond quickly enough.: MessagingTimeout: Timed out waiting for a reply to message ID cf740b480bd84733877cc59e17803645
2019-12-10 10:58:36.087 1838419 WARNING neutron.common.rpc [req-1d88bbfd-ff27-4760-aba5-550b02849e6b - - - - -] Increasing timeout for update_device_up calls to 120 seconds. Restart the agent to restore it to the default value.: MessagingTimeout: Timed out waiting for a reply to message ID cf740b480bd84733877cc59e17803645
2019-12-10 10:58:41.447 1838419 INFO neutron.plugins.ml2.drivers.agent._common_agent [-] Stopping Linux bridge agent agent.
2019-12-10 10:58:41.449 1838419 ERROR root [req-1d88bbfd-ff27-4760-aba5-550b02849e6b - - - - -] Original exception being dropped: ['Traceback (most recent call last):\n', '  File "/usr/lib/python2.7/dist-packages/neutron/common/rpc.py", line 150, in call\n    return self._original_context.call(ctxt, method, **kwargs)\n', '  File "/usr/lib/python2.7/dist-packages/oslo_messaging/rpc/client.py", line 179, in call\n    retry=self.retry)\n', '  File "/usr/lib/python2.7/dist-packages/oslo_messaging/transport.py", line 133, in _send\n    retry=retry)\n', '  File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 584, in send\n    call_monitor_timeout, retry=retry)\n', '  File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 573, in _send\n    call_monitor_timeout)\n', '  File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 459, in wait\n    message = self.waiters.get(msg_id, timeout=timeout)\n', '  File "/usr/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 336, in get\n    \'to message ID %s\' % msg_id)\n', 'MessagingTimeout: Timed out waiting for a reply to message ID cf740b480bd84733877cc59e17803645\n']: GreenletExit
2019-12-10 10:58:41.453 1838419 INFO oslo_rootwrap.client [-] Stopping rootwrap daemon process with pid=1838513
2019-12-10 10:58:52.545 1840050 INFO neutron.common.config [-] Logging enabled!
2019-12-10 10:58:52.546 1840050 INFO neutron.common.config [-] /usr/bin/neutron-linuxbridge-agent version 13.0.4
2019-12-10 10:58:52.546 1840050 INFO neutron.plugins.ml2.drivers.linuxbridge.agent.linuxbridge_neutron_agent [-] Interface mappings: {'physnet1': 'bond0'}
2019-12-10 10:58:52.546 1840050 INFO neutron.plugins.ml2.drivers.linuxbridge.agent.linuxbridge_neutron_agent [-] Bridge mappings: {}
2019-12-10 10:58:52.548 1840050 INFO oslo.privsep.daemon [-] Running privsep helper: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'privsep-helper', '--config-file', '/etc/neutron/neutron.conf', '--config-file', '/etc/neutron/plugins/ml2/linuxbridge_agent.ini', '--privsep_context', 'neutron.privileged.default', '--privsep_sock_path', '/tmp/tmp32gUn8/privsep.sock']
2019-12-10 10:58:53.150 1840050 INFO oslo.privsep.daemon [-] Spawned new privsep daemon via rootwrap
2019-12-10 10:58:53.078 1840101 INFO oslo.privsep.daemon [-] privsep daemon starting

Revision history for this message

Albert Braden (ozzzo) wrote on 2019-12-11:

Download full text (6.3 KiB)

I didn't check RMQ status yesterday after restarting Neutron services, but I can check it now. After running for a day the neutron-metadata-agent.log is almost all errors and VMs cannot build. Here's the RMQ status and cluster_status:

root@us01odc-p02-ctrl1:/var/log/nova# rabbitmqctl status
Status of node 'rabbit@us01odc-p02-ctrl1'
[{pid,1926926},
{running_applications,
     [{rabbit,"RabbitMQ","3.6.10"},
      {mnesia,"MNESIA CXC 138 12","4.15.3"},
      {ranch,"Socket acceptor pool for TCP protocols.","1.3.0"},
      {ssl,"Erlang/OTP SSL application","8.2.3"},
      {public_key,"Public key infrastructure","1.5.2"},
      {asn1,"The Erlang ASN1 compiler version 5.0.4","5.0.4"},
      {rabbit_common,
          "Modules shared by rabbitmq-server and rabbitmq-erlang-client",
          "3.6.10"},
      {compiler,"ERTS CXC 138 10","7.1.4"},
      {xmerl,"XML parser","1.3.16"},
      {crypto,"CRYPTO","4.2"},
      {os_mon,"CPO CXC 138 46","2.4.4"},
      {syntax_tools,"Syntax tools","2.1.4"},
      {sasl,"SASL CXC 138 11","3.1.1"},
      {stdlib,"ERTS CXC 138 10","3.4.3"},
      {kernel,"ERTS CXC 138 10","5.4.1"}]},
{os,{unix,linux}},
{erlang_version,
     "Erlang/OTP 20 [erts-9.2] [source] [64-bit] [smp:48:48] [ds:48:48:10] [async-threads:768] [kernel-poll:true]\n"},
{memory,
     [{total,2678094784},
      {connection_readers,109660624},
      {connection_writers,10235008},
      {connection_channels,262634328},
      {connection_other,220976648},
      {queue_procs,333485128},
      {queue_slave_procs,377952},
      {plugins,0},
      {other_proc,67189592},
      {mnesia,19216376},
      {metrics,14410456},
      {mgmt_db,0},
      {msg_index,1846528},
      {other_ets,23565736},
      {binary,1545825448},
      {code,21401226},
      {atom,900041},
      {other_system,60777341}]},
{alarms,[]},
{listeners,[{clustering,25672,"::"},{amqp,5672,"::"}]},
{vm_memory_high_watermark,0.4},
{vm_memory_limit,39982369996},
{disk_free_limit,50000000},
{disk_free,82705231872},
{file_descriptors,
     [{total_limit,65436},
      {total_used,4068},
      {sockets_limit,58890},
      {sockets_used,4066}]},
{processes,[{limit,1048576},{used,65120}]},
{run_queue,0},
{uptime,62151},
{kernel,{net_ticktime,60}}]
root@us01odc-p02-ctrl1:/var/log/nova# rabbitmqctl cluster_status
Cluster status of node 'rabbit@us01odc-p02-ctrl1'
[{nodes,[{disc,['rabbit@us01odc-p02-ctrl1','rabbit@us01odc-p02-ctrl2',
                'rabbit@us01odc-p02-ctrl3']}]},
{running_nodes,['rabbit@us01odc-p02-ctrl2','rabbit@us01odc-p02-ctrl3',
                 'rabbit@us01odc-p02-ctrl1']},
{cluster_name,<<"<email address hidden>">>},
{partitions,[]},
{alarms,[{'rabbit@us01odc-p02-ctrl2',[]},
          {'rabbit@us01odc-p02-ctrl3',[]},
          {'rabbit@us01odc-p02-ctrl1',[]}]}]

This is what neutron-metadata-agent.log looks like now:

root@us01odc-p02-ctrl1:/var/log/nova# rabbitmqctl status
Status of node 'rabbit@us01odc-p02-ctrl1'
[{pid,1926926},
 {running_applications,
     [{rabbit,"RabbitMQ","3.6.10"},
      {mnesia,"MNESIA  CXC 138 12","4.15.3"},
      {ranch,"Socket acceptor pool for TCP protocols.","1.3.0"},
      {ssl,"Erlang/OTP SSL application","8.2.3"},
      {public_key,"Public key infrastructure","1.5.2"},
      {asn1,"The Erlang ASN1 compiler version 5.0.4","5.0.4"},
      {rabbit_common,
          "Modules shared by rabbitmq-server and rabbitmq-erlang-client",
          "3.6.10"},
      {compiler,"ERTS  CXC 138 10","7.1.4"},
      {xmerl,"XML parser","1.3.16"},
      {crypto,"CRYPTO","4.2"},
      {os_mon,"CPO  CXC 138 46","2.4.4"},
      {syntax_tools,"Syntax tools","2.1.4"},
      {sasl,"SASL  CXC 138 11","3.1.1"},
      {stdlib,"ERTS  CXC 138 10","3.4.3"},
      {kernel,"ERTS  CXC 138 10","5.4.1"}]},
 {os,{unix,linux}},
 {erlang_version,
     "Erlang/OTP 20 [erts-9.2] [source] [64-bit] [smp:48:48] [ds:48:48:10] [async-threads:768] [kernel-poll:true]\n"},
 {memory,
     [{total,2678094784},
      {connection_readers,109660624},
      {connection_writers,10235008},
      {connection_channels,262634328},
      {connection_other,220976648},
      {queue_procs,333485128},
      {queue_slave_procs,377952},
      {plugins,0},
      {other_proc,67189592},
      {mnesia,19216376},
      {metrics,14410456},
      {mgmt_db,0},
      {msg_index,1846528},
      {other_ets,23565736},
      {binary,1545825448},
      {code,21401226},
      {atom,900041},
      {other_system,60777341}]},
 {alarms,[]},
 {listeners,[{clustering,25672,"::"},{amqp,5672,"::"}]},
 {vm_memory_high_watermark,0.4},
 {vm_memory_limit,39982369996},
 {disk_free_limit,50000000},
 {disk_free,82705231872},
 {file_descriptors,
     [{total_limit,65436},
      {total_used,4068},
      {sockets_limit,58890},
      {sockets_used,4066}]},
 {processes,[{limit,1048576},{used,65120}]},
 {run_queue,0},
 {uptime,62151},
 {kernel,{net_ticktime,60}}]
root@us01odc-p02-ctrl1:/var/log/nova# rabbitmqctl cluster_status
Cluster status of node 'rabbit@us01odc-p02-ctrl1'
[{nodes,[{disc,['rabbit@us01odc-p02-ctrl1','rabbit@us01odc-p02-ctrl2',
                'rabbit@us01odc-p02-ctrl3']}]},
 {running_nodes,['rabbit@us01odc-p02-ctrl2','rabbit@us01odc-p02-ctrl3',
                 'rabbit@us01odc-p02-ctrl1']},
 {cluster_name,<<"rabbit@us01odc-p02-ctrl1.internal.synopsys.com">>},
 {partitions,[]},
 {alarms,[{'rabbit@us01odc-p02-ctrl2',[]},
          {'rabbit@us01odc-p02-ctrl3',[]},
          {'rabbit@us01odc-p02-ctrl1',[]}]}]

This is what neutron-metadata-agent.log looks like now:

2019-12-11 10:01:52.393 1932065 INFO eventlet.wsgi.server [-] 10.195.65.93,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200  len: 0 time: 349.4078939
2019-12-11 10:01:52.395 1932068 INFO eventlet.wsgi.server [-] Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/eventlet/wsgi.py", line 521, in handle_one_response
    write(b''.join(towrite))
  File "/usr/lib/python2.7/dist-packages/eventlet/wsgi.py", line 462, in write
    wfile.flush()
  File "/usr/lib/python2.7/socket.py", line 307, in flush
    self._sock.sendall(view[write_offset:write_offset+buffer_size])
  File "/usr/lib/python2.7/dist-packages/eventlet/greenio/base.py", line 390, in sendall
    tail = self.send(data, flags)
  File "/usr/lib/python2.7/dist-packages/eventlet/greenio/base.py", line 384, in send
    return self._send_loop(self.fd.send, data, flags)
  File "/usr/lib/python2.7/dist-packages/eventlet/greenio/base.py", line 371, in _send_loop
    return send_method(data, *args)
error: [Errno 32] Broken pipe

2019-12-11 10:01:52.395 1932068 INFO eventlet.wsgi.server [-] 10.195.65.61,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200  len: 0 time: 349.6991570
2019-12-11 10:01:52.468 1932068 INFO eventlet.wsgi.server [-] 10.195.65.130,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200  len: 146 time: 0.0711129
2019-12-11 10:01:52.535 1932068 INFO eventlet.wsgi.server [-] 10.195.65.93,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200  len: 146 time: 0.0665698
2019-12-11 10:01:52.570 1932082 INFO eventlet.wsgi.server [-] Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/eventlet/wsgi.py", line 521, in handle_one_response
    write(b''.join(towrite))
  File "/usr/lib/python2.7/dist-packages/eventlet/wsgi.py", line 462, in write
    wfile.flush()
  File "/usr/lib/python2.7/socket.py", line 307, in flush
    self._sock.sendall(view[write_offset:write_offset+buffer_size])
  File "/usr/lib/python2.7/dist-packages/eventlet/greenio/base.py", line 390, in sendall
    tail = self.send(data, flags)
  File "/usr/lib/python2.7/dist-packages/eventlet/greenio/base.py", line 384, in send
    return self._send_loop(self.fd.send, data, flags)
  File "/usr/lib/python2.7/dist-packages/eventlet/greenio/base.py", line 371, in _send_loop
    return send_method(data, *args)
error: [Errno 32] Broken pipe

2019-12-11 10:01:52.571 1932082 INFO eventlet.wsgi.server [-] 10.195.65.30,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200  len: 0 time: 349.5199540
2019-12-11 10:01:52.642 1932062 INFO eventlet.wsgi.server [-] Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/eventlet/wsgi.py", line 521, in handle_one_response
    write(b''.join(towrite))
  File "/usr/lib/python2.7/dist-packages/eventlet/wsgi.py", line 462, in write
    wfile.flush()
  File "/usr/lib/python2.7/socket.py", line 307, in flush
    self._sock.sendall(view[write_offset:write_offset+buffer_size])
  File "/usr/lib/python2.7/dist-packages/eventlet/greenio/base.py", line 390, in sendall
    tail = self.send(data, flags)
  File "/usr/lib/python2.7/dist-packages/eventlet/greenio/base.py", line 384, in send
    return self._send_loop(self.fd.send, data, flags)
  File "/usr/lib/python2.7/dist-packages/eventlet/greenio/base.py", line 371, in _send_loop
    return send_method(data, *args)
error: [Errno 32] Broken pipe

2019-12-11 10:01:52.642 1932062 INFO eventlet.wsgi.server [-] 10.195.65.37,<local> "GET /latest/meta-data/instance-id HTTP/1.0" status: 200  len: 0 time: 349.3136029

Revision history for this message

Albert Braden (ozzzo) wrote on 2019-12-11:

Download full text (61.3 KiB)

Here's the MySQL status:

root@us01odc-p02-ctrl1:/var/log/nova# mysql -e "show status"
+--------------------------------------------------------------+--------------------------------------------------+
| Variable_name                                                | Value                                            |
+--------------------------------------------------------------+--------------------------------------------------+
| Aborted_clients                                              | 14089                                            |
| Aborted_connects                                             | 4                                                |
| Access_denied_errors                                         | 0                                                |
| Acl_column_grants                                            | 0                                                |
| Acl_database_grants                                          | 16                                               |
| Acl_function_grants                                          | 0                                                |
| Acl_procedure_grants                                         | 0                                                |
| Acl_package_spec_grants                                      | 0                                                |
| Acl_package_body_grants                                      | 0                                                |
| Acl_proxy_users                                              | 1                                                |
| Acl_role_grants                                              | 0                                                |
| Acl_roles                                                    | 0                                                |
| Acl_table_grants                                             | 0                                                |
| Acl_users                                                    | 20                                               |
| Aria_pagecache_blocks_not_flushed                            | 0                                                |
| Aria_pagecache_blocks_unused                                 | 15706                                            |
| Aria_pagecache_blocks_used                                   | 389                                              |
| Aria_pagecache_read_requests                                 | 103205350                                        |
| Aria_pagecache_reads                                         | 30418596                                         |
| Aria_pagecache_write_requests                                | 61739452                                         |
| Aria_pagecache_writes                                        | 61739452                                         |
| Aria_transaction_log_syncs                                   | 22785                                            |
| Binlog_commits                                               | 0                                                |
| Binlog_group_commits                                         | 0                                                |
| Binlog_group_commit_trigger_count                            | 0                                                |
| Binlog_group_commit_trigger_lock_wait                        | 0                                                |
| Binlog_group_commit_trigger_timeout                          | 0                                                |
| Binlog_snapshot_file                                         |                                                  |
| Binlog_snapshot_position                                     | 0                                                |
| Binlog_bytes_written                                         | 0                                                |
| Binlog_cache_disk_use                                        | 0                                                |
| Binlog_cache_use                                             | 0                                                |
| Binlog_stmt_cache_disk_use                                   | 0                                                |
| Binlog_stmt_cache_use                                        | 0                                                |
| Busy_time                                                    | 0.000000                                         |
| Bytes_received                                               | 206                                              |
| Bytes_sent                                                   | 127                                              |
| Column_compressions                                          | 0                                                |
| Column_decompressions                                        | 0                                                |
| Com_admin_commands                                           | 0                                                |
| Com_alter_db                                                 | 0                                                |
| Com_alter_db_upgrade                                         | 0                                                |
| Com_alter_event                                              | 0                                                |
| Com_alter_function                                           | 0                                                |
| Com_alter_procedure                                          | 0                                                |
| Com_alter_server                                             | 0                                                |
| Com_alter_sequence                                           | 0                                                |
| Com_alter_table                                              | 0                                                |
| Com_alter_tablespace                                         | 0                                                |
| Com_alter_user                                               | 0                                                |
| Com_analyze                                                  | 0                                                |
| Com_assign_to_keycache                                       | 0                                                |
| Com_begin                                                    | 0                                                |
| Com_binlog                                                   | 0                                                |
| Com_call_procedure                                           | 0                                                |
| Com_change_db                                                | 0                                                |
| Com_change_master                                            | 0                                                |
| Com_check                                                    | 0                                                |
| Com_checksum                                                 | 0                                                |
| Com_commit                                                   | 0                                                |
| Com_compound_sql                                             | 0                                                |
| Com_create_db                                                | 0                                                |
| Com_create_event                                             | 0                                                |
| Com_create_function                                          | 0                                                |
| Com_create_index                                             | 0                                                |
| Com_create_package                                           | 0                                                |
| Com_create_package_body                                      | 0                                                |
| Com_create_procedure                                         | 0                                                |
| Com_create_role                                              | 0                                                |
| Com_create_sequence                                          | 0                                                |
| Com_create_server                                            | 0                                                |
| Com_create_table                                             | 0                                                |
| Com_create_temporary_table                                   | 0                                                |
| Com_create_trigger                                           | 0                                                |
| Com_create_udf                                               | 0                                                |
| Com_create_user                                              | 0                                                |
| Com_create_view                                              | 0                                                |
| Com_dealloc_sql                                              | 0                                                |
| Com_delete                                                   | 0                                                |
| Com_delete_multi                                             | 0                                                |
| Com_do                                                       | 0                                                |
| Com_drop_db                                                  | 0                                                |
| Com_drop_event                                               | 0                                                |
| Com_drop_function                                            | 0                                                |
| Com_drop_index                                               | 0                                                |
| Com_drop_procedure                                           | 0                                                |
| Com_drop_package                                             | 0                                                |
| Com_drop_package_body                                        | 0                                                |
| Com_drop_role                                                | 0                                                |
| Com_drop_server                                              | 0                                                |
| Com_drop_sequence                                            | 0                                                |
| Com_drop_table                                               | 0                                                |
| Com_drop_temporary_table                                     | 0                                                |
| Com_drop_trigger                                             | 0                                                |
| Com_drop_user                                                | 0                                                |
| Com_drop_view                                                | 0                                                |
| Com_empty_query                                              | 0                                                |
| Com_execute_immediate                                        | 0                                                |
| Com_execute_sql                                              | 0                                                |
| Com_flush                                                    | 0                                                |
| Com_get_diagnostics                                          | 0                                                |
| Com_grant                                                    | 0                                                |
| Com_grant_role                                               | 0                                                |
| Com_ha_close                                                 | 0                                                |
| Com_ha_open                                                  | 0                                                |
| Com_ha_read                                                  | 0                                                |
| Com_help                                                     | 0                                                |
| Com_insert                                                   | 0                                                |
| Com_insert_select                                            | 0                                                |
| Com_install_plugin                                           | 0                                                |
| Com_kill                                                     | 0                                                |
| Com_load                                                     | 0                                                |
| Com_lock_tables                                              | 0                                                |
| Com_multi                                                    | 0                                                |
| Com_optimize                                                 | 0                                                |
| Com_preload_keys                                             | 0                                                |
| Com_prepare_sql                                              | 0                                                |
| Com_purge                                                    | 0                                                |
| Com_purge_before_date                                        | 0                                                |
| Com_release_savepoint                                        | 0                                                |
| Com_rename_table                                             | 0                                                |
| Com_rename_user                                              | 0                                                |
| Com_repair                                                   | 0                                                |
| Com_replace                                                  | 0                                                |
| Com_replace_select                                           | 0                                                |
| Com_reset                                                    | 0                                                |
| Com_resignal                                                 | 0                                                |
| Com_revoke                                                   | 0                                                |
| Com_revoke_all                                               | 0                                                |
| Com_revoke_role                                              | 0                                                |
| Com_rollback                                                 | 0                                                |
| Com_rollback_to_savepoint                                    | 0                                                |
| Com_savepoint                                                | 0                                                |
| Com_select                                                   | 0                                                |
| Com_set_option                                               | 0                                                |
| Com_show_authors                                             | 0                                                |
| Com_show_binlog_events                                       | 0                                                |
| Com_show_binlogs                                             | 0                                                |
| Com_show_charsets                                            | 0                                                |
| Com_show_collations                                          | 0                                                |
| Com_show_contributors                                        | 0                                                |
| Com_show_create_db                                           | 0                                                |
| Com_show_create_event                                        | 0                                                |
| Com_show_create_func                                         | 0                                                |
| Com_show_create_package                                      | 0                                                |
| Com_show_create_package_body                                 | 0                                                |
| Com_show_create_proc                                         | 0                                                |
| Com_show_create_table                                        | 0                                                |
| Com_show_create_trigger                                      | 0                                                |
| Com_show_create_user                                         | 0                                                |
| Com_show_databases                                           | 0                                                |
| Com_show_engine_logs                                         | 0                                                |
| Com_show_engine_mutex                                        | 0                                                |
| Com_show_engine_status                                       | 0                                                |
| Com_show_errors                                              | 0                                                |
| Com_show_events                                              | 0                                                |
| Com_show_explain                                             | 0                                                |
| Com_show_fields                                              | 0                                                |
| Com_show_function_status                                     | 0                                                |
| Com_show_generic                                             | 0                                                |
| Com_show_grants                                              | 0                                                |
| Com_show_keys                                                | 0                                                |
| Com_show_master_status                                       | 0                                                |
| Com_show_open_tables                                         | 0                                                |
| Com_show_package_status                                      | 0                                                |
| Com_show_package_body_status                                 | 0                                                |
| Com_show_plugins                                             | 0                                                |
| Com_show_privileges                                          | 0                                                |
| Com_show_procedure_status                                    | 0                                                |
| Com_show_processlist                                         | 0                                                |
| Com_show_profile                                             | 0                                                |
| Com_show_profiles                                            | 0                                                |
| Com_show_relaylog_events                                     | 0                                                |
| Com_show_slave_hosts                                         | 0                                                |
| Com_show_slave_status                                        | 0                                                |
| Com_show_status                                              | 1                                                |
| Com_show_storage_engines                                     | 0                                                |
| Com_show_table_status                                        | 0                                                |
| Com_show_tables                                              | 0                                                |
| Com_show_triggers                                            | 0                                                |
| Com_show_variables                                           | 0                                                |
| Com_show_warnings                                            | 0                                                |
| Com_shutdown                                                 | 0                                                |
| Com_signal                                                   | 0                                                |
| Com_start_all_slaves                                         | 0                                                |
| Com_start_slave                                              | 0                                                |
| Com_stmt_close                                               | 0                                                |
| Com_stmt_execute                                             | 0                                                |
| Com_stmt_fetch                                               | 0                                                |
| Com_stmt_prepare                                             | 0                                                |
| Com_stmt_reprepare                                           | 0                                                |
| Com_stmt_reset                                               | 0                                                |
| Com_stmt_send_long_data                                      | 0                                                |
| Com_stop_all_slaves                                          | 0                                                |
| Com_stop_slave                                               | 0                                                |
| Com_truncate                                                 | 0                                                |
| Com_uninstall_plugin                                         | 0                                                |
| Com_unlock_tables                                            | 0                                                |
| Com_update                                                   | 0                                                |
| Com_update_multi                                             | 0                                                |
| Com_xa_commit                                                | 0                                                |
| Com_xa_end                                                   | 0                                                |
| Com_xa_prepare                                               | 0                                                |
| Com_xa_recover                                               | 0                                                |
| Com_xa_rollback                                              | 0                                                |
| Com_xa_start                                                 | 0                                                |
| Compression                                                  | OFF                                              |
| Connection_errors_accept                                     | 0                                                |
| Connection_errors_internal                                   | 0                                                |
| Connection_errors_max_connections                            | 0                                                |
| Connection_errors_peer_address                               | 0                                                |
| Connection_errors_select                                     | 0                                                |
| Connection_errors_tcpwrap                                    | 0                                                |
| Connections                                                  | 4107366                                          |
| Cpu_time                                                     | 0.000000                                         |
| Created_tmp_disk_tables                                      | 0                                                |
| Created_tmp_files                                            | 5                                                |
| Created_tmp_tables                                           | 0                                                |
| Delayed_errors                                               | 0                                                |
| Delayed_insert_threads                                       | 0                                                |
| Delayed_writes                                               | 0                                                |
| Delete_scan                                                  | 0                                                |
| Empty_queries                                                | 0                                                |
| Executed_events                                              | 0                                                |
| Executed_triggers                                            | 0                                                |
| Feature_check_constraint                                     | 108                                              |
| Feature_custom_aggregate_functions                           | 0                                                |
| Feature_delay_key_write                                      | 0                                                |
| Feature_dynamic_columns                                      | 0                                                |
| Feature_fulltext                                             | 0                                                |
| Feature_gis                                                  | 0                                                |
| Feature_invisible_columns                                    | 0                                                |
| Feature_json                                                 | 0                                                |
| Feature_locale                                               | 0                                                |
| Feature_subquery                                             | 0                                                |
| Feature_system_versioning                                    | 0                                                |
| Feature_timezone                                             | 0                                                |
| Feature_trigger                                              | 0                                                |
| Feature_window_functions                                     | 0                                                |
| Feature_xml                                                  | 0                                                |
| Flush_commands                                               | 1                                                |
| Handler_commit                                               | 0                                                |
| Handler_delete                                               | 0                                                |
| Handler_discover                                             | 0                                                |
| Handler_external_lock                                        | 0                                                |
| Handler_icp_attempts                                         | 0                                                |
| Handler_icp_match                                            | 0                                                |
| Handler_mrr_init                                             | 0                                                |
| Handler_mrr_key_refills                                      | 0                                                |
| Handler_mrr_rowid_refills                                    | 0                                                |
| Handler_prepare                                              | 0                                                |
| Handler_read_first                                           | 0                                                |
| Handler_read_key                                             | 0                                                |
| Handler_read_last                                            | 0                                                |
| Handler_read_next                                            | 0                                                |
| Handler_read_prev                                            | 0                                                |
| Handler_read_retry                                           | 0                                                |
| Handler_read_rnd                                             | 0                                                |
| Handler_read_rnd_deleted                                     | 0                                                |
| Handler_read_rnd_next                                        | 0                                                |
| Handler_rollback                                             | 0                                                |
| Handler_savepoint                                            | 0                                                |
| Handler_savepoint_rollback                                   | 0                                                |
| Handler_tmp_delete                                           | 0                                                |
| Handler_tmp_update                                           | 0                                                |
| Handler_tmp_write                                            | 0                                                |
| Handler_update                                               | 0                                                |
| Handler_write                                                | 0                                                |
| Innodb_buffer_pool_dump_status                               |                                                  |
| Innodb_buffer_pool_load_status                               | Buffer pool(s) load completed at 191203 11:12:05 |
| Innodb_buffer_pool_resize_status                             |                                                  |
| Innodb_buffer_pool_load_incomplete                           | OFF                                              |
| Innodb_buffer_pool_pages_data                                | 11838                                            |
| Innodb_buffer_pool_bytes_data                                | 193953792                                        |
| Innodb_buffer_pool_pages_dirty                               | 69                                               |
| Innodb_buffer_pool_bytes_dirty                               | 1130496                                          |
| Innodb_buffer_pool_pages_flushed                             | 46826365                                         |
| Innodb_buffer_pool_pages_free                                | 4266                                             |
| Innodb_buffer_pool_pages_misc                                | 280                                              |
| Innodb_buffer_pool_pages_total                               | 16384                                            |
| Innodb_buffer_pool_read_ahead_rnd                            | 0                                                |
| Innodb_buffer_pool_read_ahead                                | 0                                                |
| Innodb_buffer_pool_read_ahead_evicted                        | 0                                                |
| Innodb_buffer_pool_read_requests                             | 104494918886                                     |
| Innodb_buffer_pool_reads                                     | 10061                                            |
| Innodb_buffer_pool_wait_free                                 | 0                                                |
| Innodb_buffer_pool_write_requests                            | 169077519                                        |
| Innodb_data_fsyncs                                           | 27522948                                         |
| Innodb_data_pending_fsyncs                                   | 0                                                |
| Innodb_data_pending_reads                                    | 0                                                |
| Innodb_data_pending_writes                                   | 0                                                |
| Innodb_data_read                                             | 166889984                                        |
| Innodb_data_reads                                            | 10436                                            |
| Innodb_data_writes                                           | 71939691                                         |
| Innodb_data_written                                          | 1562398620160                                    |
| Innodb_dblwr_pages_written                                   | 46826234                                         |
| Innodb_dblwr_writes                                          | 1353799                                          |
| Innodb_log_waits                                             | 0                                                |
| Innodb_log_write_requests                                    | 16360684                                         |
| Innodb_log_writes                                            | 23647743                                         |
| Innodb_os_log_fsyncs                                         | 23746090                                         |
| Innodb_os_log_pending_fsyncs                                 | 0                                                |
| Innodb_os_log_pending_writes                                 | 0                                                |
| Innodb_os_log_written                                        | 27946229760                                      |
| Innodb_page_size                                             | 16384                                            |
| Innodb_pages_created                                         | 1657                                             |
| Innodb_pages_read                                            | 10181                                            |
| Innodb_pages0_read                                           | 244                                              |
| Innodb_pages_written                                         | 46826365                                         |
| Innodb_row_lock_current_waits                                | 0                                                |
| Innodb_row_lock_time                                         | 242885                                           |
| Innodb_row_lock_time_avg                                     | 1                                                |
| Innodb_row_lock_time_max                                     | 562                                              |
| Innodb_row_lock_waits                                        | 221139                                           |
| Innodb_rows_deleted                                          | 23267                                            |
| Innodb_rows_inserted                                         | 54255                                            |
| Innodb_rows_read                                             | 40330101823                                      |
| Innodb_rows_updated                                          | 23195180                                         |
| Innodb_system_rows_deleted                                   | 0                                                |
| Innodb_system_rows_inserted                                  | 0                                                |
| Innodb_system_rows_read                                      | 0                                                |
| Innodb_system_rows_updated                                   | 0                                                |
| Innodb_num_open_files                                        | 247                                              |
| Innodb_truncated_status_writes                               | 0                                                |
| Innodb_available_undo_logs                                   | 128                                              |
| Innodb_undo_truncations                                      | 0                                                |
| Innodb_page_compression_saved                                | 0                                                |
| Innodb_num_index_pages_written                               | 0                                                |
| Innodb_num_non_index_pages_written                           | 0                                                |
| Innodb_num_pages_page_compressed                             | 0                                                |
| Innodb_num_page_compressed_trim_op                           | 0                                                |
| Innodb_num_pages_page_decompressed                           | 0                                                |
| Innodb_num_pages_page_compression_error                      | 0                                                |
| Innodb_num_pages_encrypted                                   | 0                                                |
| Innodb_num_pages_decrypted                                   | 0                                                |
| Innodb_have_lz4                                              | ON                                               |
| Innodb_have_lzo                                              | OFF                                              |
| Innodb_have_lzma                                             | OFF                                              |
| Innodb_have_bzip2                                            | OFF                                              |
| Innodb_have_snappy                                           | OFF                                              |
| Innodb_have_punch_hole                                       | ON                                               |
| Innodb_defragment_compression_failures                       | 0                                                |
| Innodb_defragment_failures                                   | 0                                                |
| Innodb_defragment_count                                      | 0                                                |
| Innodb_instant_alter_column                                  | 0                                                |
| Innodb_onlineddl_rowlog_rows                                 | 0                                                |
| Innodb_onlineddl_rowlog_pct_used                             | 0                                                |
| Innodb_onlineddl_pct_progress                                | 0                                                |
| Innodb_secondary_index_triggered_cluster_reads               | 2477019165                                       |
| Innodb_secondary_index_triggered_cluster_reads_avoided       | 0                                                |
| Innodb_encryption_rotation_pages_read_from_cache             | 0                                                |
| Innodb_encryption_rotation_pages_read_from_disk              | 0                                                |
| Innodb_encryption_rotation_pages_modified                    | 0                                                |
| Innodb_encryption_rotation_pages_flushed                     | 0                                                |
| Innodb_encryption_rotation_estimated_iops                    | 0                                                |
| Innodb_encryption_key_rotation_list_length                   | 0                                                |
| Innodb_encryption_n_merge_blocks_encrypted                   | 0                                                |
| Innodb_encryption_n_merge_blocks_decrypted                   | 0                                                |
| Innodb_encryption_n_rowlog_blocks_encrypted                  | 0                                                |
| Innodb_encryption_n_rowlog_blocks_decrypted                  | 0                                                |
| Innodb_encryption_n_temp_blocks_encrypted                    | 0                                                |
| Innodb_encryption_n_temp_blocks_decrypted                    | 0                                                |
| Innodb_scrub_background_page_reorganizations                 | 0                                                |
| Innodb_scrub_background_page_splits                          | 0                                                |
| Innodb_scrub_background_page_split_failures_underflow        | 0                                                |
| Innodb_scrub_background_page_split_failures_out_of_filespace | 0                                                |
| Innodb_scrub_background_page_split_failures_missing_index    | 0                                                |
| Innodb_scrub_background_page_split_failures_unknown          | 0                                                |
| Innodb_scrub_log                                             | 0                                                |
| Innodb_encryption_num_key_requests                           | 0                                                |
| Key_blocks_not_flushed                                       | 0                                                |
| Key_blocks_unused                                            | 107163                                           |
| Key_blocks_used                                              | 2                                                |
| Key_blocks_warm                                              | 0                                                |
| Key_read_requests                                            | 156                                              |
| Key_reads                                                    | 6                                                |
| Key_write_requests                                           | 0                                                |
| Key_writes                                                   | 0                                                |
| Last_query_cost                                              | 0.000000                                         |
| Master_gtid_wait_count                                       | 0                                                |
| Master_gtid_wait_time                                        | 0                                                |
| Master_gtid_wait_timeouts                                    | 0                                                |
| Max_statement_time_exceeded                                  | 0                                                |
| Max_used_connections                                         | 1776                                             |
| Memory_used                                                  | 77776                                            |
| Memory_used_initial                                          | 340762840                                        |
| Not_flushed_delayed_rows                                     | 0                                                |
| Open_files                                                   | 5                                                |
| Open_streams                                                 | 0                                                |
| Open_table_definitions                                       | 400                                              |
| Open_tables                                                  | 800                                              |
| Opened_files                                                 | 121673469                                        |
| Opened_plugin_libraries                                      | 0                                                |
| Opened_table_definitions                                     | 0                                                |
| Opened_tables                                                | 0                                                |
| Opened_views                                                 | 0                                                |
| Performance_schema_accounts_lost                             | 0                                                |
| Performance_schema_cond_classes_lost                         | 0                                                |
| Performance_schema_cond_instances_lost                       | 0                                                |
| Performance_schema_digest_lost                               | 0                                                |
| Performance_schema_file_classes_lost                         | 0                                                |
| Performance_schema_file_handles_lost                         | 0                                                |
| Performance_schema_file_instances_lost                       | 0                                                |
| Performance_schema_hosts_lost                                | 0                                                |
| Performance_schema_locker_lost                               | 0                                                |
| Performance_schema_mutex_classes_lost                        | 0                                                |
| Performance_schema_mutex_instances_lost                      | 0                                                |
| Performance_schema_rwlock_classes_lost                       | 0                                                |
| Performance_schema_rwlock_instances_lost                     | 0                                                |
| Performance_schema_session_connect_attrs_lost                | 0                                                |
| Performance_schema_socket_classes_lost                       | 0                                                |
| Performance_schema_socket_instances_lost                     | 0                                                |
| Performance_schema_stage_classes_lost                        | 0                                                |
| Performance_schema_statement_classes_lost                    | 0                                                |
| Performance_schema_table_handles_lost                        | 0                                                |
| Performance_schema_table_instances_lost                      | 0                                                |
| Performance_schema_thread_classes_lost                       | 0                                                |
| Performance_schema_thread_instances_lost                     | 0                                                |
| Performance_schema_users_lost                                | 0                                                |
| Prepared_stmt_count                                          | 0                                                |
| Qcache_free_blocks                                           | 2143                                             |
| Qcache_free_memory                                           | 5416752                                          |
| Qcache_hits                                                  | 294072437                                        |
| Qcache_inserts                                               | 221348217                                        |
| Qcache_lowmem_prunes                                         | 178071190                                        |
| Qcache_not_cached                                            | 1383275069                                       |
| Qcache_queries_in_cache                                      | 10486                                            |
| Qcache_total_blocks                                          | 25834                                            |
| Queries                                                      | 2923569239                                       |
| Questions                                                    | 1                                                |
| Rows_read                                                    | 0                                                |
| Rows_sent                                                    | 0                                                |
| Rows_tmp_read                                                | 0                                                |
| Rpl_semi_sync_master_clients                                 | 0                                                |
| Rpl_semi_sync_master_get_ack                                 | 0                                                |
| Rpl_semi_sync_master_net_avg_wait_time                       | 0                                                |
| Rpl_semi_sync_master_net_wait_time                           | 0                                                |
| Rpl_semi_sync_master_net_waits                               | 0                                                |
| Rpl_semi_sync_master_no_times                                | 0                                                |
| Rpl_semi_sync_master_no_tx                                   | 0                                                |
| Rpl_semi_sync_master_request_ack                             | 0                                                |
| Rpl_semi_sync_master_status                                  | OFF                                              |
| Rpl_semi_sync_master_timefunc_failures                       | 0                                                |
| Rpl_semi_sync_master_tx_avg_wait_time                        | 0                                                |
| Rpl_semi_sync_master_tx_wait_time                            | 0                                                |
| Rpl_semi_sync_master_tx_waits                                | 0                                                |
| Rpl_semi_sync_master_wait_pos_backtraverse                   | 0                                                |
| Rpl_semi_sync_master_wait_sessions                           | 0                                                |
| Rpl_semi_sync_master_yes_tx                                  | 0                                                |
| Rpl_semi_sync_slave_send_ack                                 | 0                                                |
| Rpl_semi_sync_slave_status                                   | OFF                                              |
| Rpl_status                                                   | AUTH_MASTER                                      |
| Rpl_transactions_multi_engine                                | 0                                                |
| Select_full_join                                             | 0                                                |
| Select_full_range_join                                       | 0                                                |
| Select_range                                                 | 0                                                |
| Select_range_check                                           | 0                                                |
| Select_scan                                                  | 0                                                |
| Slave_connections                                            | 0                                                |
| Slave_heartbeat_period                                       | 0.000                                            |
| Slave_open_temp_tables                                       | 0                                                |
| Slave_received_heartbeats                                    | 0                                                |
| Slave_retried_transactions                                   | 0                                                |
| Slave_running                                                | OFF                                              |
| Slave_skipped_errors                                         | 0                                                |
| Slaves_connected                                             | 0                                                |
| Slaves_running                                               | 0                                                |
| Slow_launch_threads                                          | 0                                                |
| Slow_queries                                                 | 0                                                |
| Sort_merge_passes                                            | 0                                                |
| Sort_priority_queue_sorts                                    | 0                                                |
| Sort_range                                                   | 0                                                |
| Sort_rows                                                    | 0                                                |
| Sort_scan                                                    | 0                                                |
| Ssl_accept_renegotiates                                      | 0                                                |
| Ssl_accepts                                                  | 0                                                |
| Ssl_callback_cache_hits                                      | 0                                                |
| Ssl_cipher                                                   |                                                  |
| Ssl_cipher_list                                              |                                                  |
| Ssl_client_connects                                          | 0                                                |
| Ssl_connect_renegotiates                                     | 0                                                |
| Ssl_ctx_verify_depth                                         | 0                                                |
| Ssl_ctx_verify_mode                                          | 0                                                |
| Ssl_default_timeout                                          | 0                                                |
| Ssl_finished_accepts                                         | 0                                                |
| Ssl_finished_connects                                        | 0                                                |
| Ssl_server_not_after                                         |                                                  |
| Ssl_server_not_before                                        |                                                  |
| Ssl_session_cache_hits                                       | 0                                                |
| Ssl_session_cache_misses                                     | 0                                                |
| Ssl_session_cache_mode                                       | NONE                                             |
| Ssl_session_cache_overflows                                  | 0                                                |
| Ssl_session_cache_size                                       | 0                                                |
| Ssl_session_cache_timeouts                                   | 0                                                |
| Ssl_sessions_reused                                          | 0                                                |
| Ssl_used_session_cache_entries                               | 0                                                |
| Ssl_verify_depth                                             | 0                                                |
| Ssl_verify_mode                                              | 0                                                |
| Ssl_version                                                  |                                                  |
| Subquery_cache_hit                                           | 0                                                |
| Subquery_cache_miss                                          | 14339854648                                      |
| Syncs                                                        | 45572                                            |
| Table_locks_immediate                                        | 122                                              |
| Table_locks_waited                                           | 0                                                |
| Table_open_cache_active_instances                            | 2                                                |
| Table_open_cache_hits                                        | 0                                                |
| Table_open_cache_misses                                      | 0                                                |
| Table_open_cache_overflows                                   | 0                                                |
| Tc_log_max_pages_used                                        | 0                                                |
| Tc_log_page_size                                             | 4096                                             |
| Tc_log_page_waits                                            | 0                                                |
| Threadpool_idle_threads                                      | 0                                                |
| Threadpool_threads                                           | 0                                                |
| Threads_cached                                               | 16                                               |
| Threads_connected                                            | 1396                                             |
| Threads_created                                              | 9761                                             |
| Threads_running                                              | 1                                                |
| Transactions_gtid_foreign_engine                             | 0                                                |
| Transactions_multi_engine                                    | 0                                                |
| Update_scan                                                  | 0                                                |
| Uptime                                                       | 689287                                           |
| Uptime_since_flush_status                                    | 689287                                           |
| wsrep_applier_thread_count                                   | 0                                                |
| wsrep_cluster_conf_id                                        | 18446744073709551615                             |
| wsrep_cluster_size                                           | 0                                                |
| wsrep_cluster_state_uuid                                     |                                                  |
| wsrep_cluster_status                                         | Disconnected                                     |
| wsrep_connected                                              | OFF                                              |
| wsrep_local_bf_aborts                                        | 0                                                |
| wsrep_local_index                                            | 18446744073709551615                             |
| wsrep_provider_name                                          |                                                  |
| wsrep_provider_vendor                                        |                                                  |
| wsrep_provider_version                                       |                                                  |
| wsrep_ready                                                  | OFF                                              |
| wsrep_rollbacker_thread_count                                | 0                                                |
| wsrep_thread_count                                           | 0                                                |
+--------------------------------------------------------------+--------------------------------------------------+

Revision history for this message

Albert Braden (ozzzo) wrote on 2019-12-11:

Load is 13 on the controllers which should be fine with 48 CPUs. We have nova, neutron and RMQ all running on 3 controllers. MySQL runs on ctrl1.

root@us01odc-p02-ctrl1:/var/log/nova# uptime
10:41:08 up 7 days, 23:29, 3 users, load average: 12.66, 13.12, 13.51
root@us01odc-p02-ctrl1:/var/log/nova# lscpu
Architecture: x86_64
CPU op-mode(s): 32-bit, 64-bit
Byte Order: Little Endian
CPU(s): 48
On-line CPU(s) list: 0-47
Thread(s) per core: 2
Core(s) per socket: 12
Socket(s): 2
NUMA node(s): 2
Vendor ID: GenuineIntel
CPU family: 6
Model: 85
Model name: Intel(R) Xeon(R) Gold 5118 CPU @ 2.30GHz
Stepping: 4
CPU MHz: 2669.000
BogoMIPS: 4600.00
Virtualization: VT-x
L1d cache: 32K
L1i cache: 32K
L2 cache: 1024K
L3 cache: 16896K
NUMA node0 CPU(s): 0-11,24-35
NUMA node1 CPU(s): 12-23,36-47
Flags: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc art arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc cpuid aperfmperf pni pclmulqdq dtes64 monitor ds_cpl vmx smx est tm2 ssse3 sdbg fma cx16 xtpr pdcm pcid dca sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm abm 3dnowprefetch cpuid_fault epb cat_l3 cdp_l3 invpcid_single pti intel_ppin ssbd mba ibrs ibpb stibp tpr_shadow vnmi flexpriority ept vpid ept_ad fsgsbase tsc_adjust bmi1 hle avx2 smep bmi2 erms invpcid rtm cqm mpx rdt_a avx512f avx512dq rdseed adx smap clflushopt clwb intel_pt avx512cd avx512bw avx512vl xsaveopt xsavec xgetbv1 xsaves cqm_llc cqm_occup_llc cqm_mbm_total cqm_mbm_local dtherm ida arat pln pts hwp_epp pku ospke md_clear flush_l1d

Changed in neutron:
status:	Incomplete → New

YAMAMOTO Takashi (yamamoto) on 2019-12-12

Changed in neutron:
importance:	Undecided → High

Revision history for this message

YAMAMOTO Takashi (yamamoto) wrote on 2019-12-12:

have you tried to bump the number of rpc workers?

Revision history for this message

Rodolfo Alonso (rodolfo-alonso-hernandez) wrote on 2019-12-12:

#10

Hello Albert:

Reviewing the agent and the server logs (not in the same time, that's a pity), the server looks healthy, replying to the API calls in a very short time. However the agent seems to have problems with the RPC calls, not receiving any reply. I can't dig more on this.

About the DB, I took a look at Innodb_row_lock_time_max (562ms) and Innodb_row_lock_time_avg (1ms). Both parameters look perfectly OK.

Can you check the connectivity from the faulty agent to the MQ? I think this is the problem you are having there. IMO, this looks like a configuration problem rather than a code one. Of course, the information I have is limited. Please, don't take this as the ultimate truth.

Regards.

Revision history for this message

Albert Braden (ozzzo) wrote on 2019-12-12:

#11

Setting rpc_workers to 8 in /etc/neutron/neutron.conf fixed the problem.

How could I have found this information without opening a bug? Is there a document that I should have read?

Revision history for this message

Albert Braden (ozzzo) wrote on 2019-12-12:

#12

It appears that the information should be added to:

https://docs.openstack.org/neutron/rocky/configuration/neutron.html.

This section:

rpc_workers

Type: integer
Default: 1
Number of RPC worker processes for service.

Should include this information:

If your neutron-metadata-agent.log is full of "error: [Errno 32] Broken pipe" then increase this setting

Revision history for this message

YAMAMOTO Takashi (yamamoto) wrote on 2019-12-13:

#13

Albert,

glad to hear it fixed the problem.

i myself found it by "git log". (later versions have larger default for rpc_workers.)

it's documented here. (for master)
https://docs.openstack.org/neutron/train/admin/config-wsgi.html#neutron-worker-processes

i don't know if it's documented for rocky.

Revision history for this message

YAMAMOTO Takashi (yamamoto) wrote on 2019-12-16:

#14

lower priority as there's a workaround. of course, documentation improvements are welcome.

Changed in neutron:
importance:	High → Low
status:	New → Opinion

Chason Chan (chen-xing) on 2019-12-17

Changed in neutron:
assignee:	nobody → Chason Chan (chen-xing)

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2019-12-17: Fix proposed to neutron (master)

#15

Fix proposed to branch: master
Review: https://review.opendev.org/699372

Changed in neutron:
status:	Opinion → In Progress

Revision history for this message

Slawek Kaplonski (slaweq) wrote on 2020-09-25: auto-abandon-script

#16

This bug has had a related patch abandoned and has been automatically un-assigned due to inactivity. Please re-assign yourself if you are continuing work or adjust the state as appropriate if it is no longer valid.

Changed in neutron:
assignee:	Chason Chan (chen-xing) → nobody
status:	In Progress → New
tags:	added: timeout-abandon

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2020-09-25: Change abandoned on neutron (master)

#17

Change abandoned by Slawek Kaplonski (<email address hidden>) on branch: master
Review: https://review.opendev.org/699372
Reason: This review is > 4 weeks without comment, and failed Zuul jobs the last time it was checked. We are abandoning this for now. Feel free to reactivate the review by pressing the restore button and leaving a 'recheck' comment to get fresh test results.

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2023-01-10: Fix proposed to neutron (master)

#18

Fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/neutron/+/869770

Changed in neutron:
status:	New → In Progress

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2023-01-12: Fix merged to neutron (master)

#19

Reviewed: https://review.opendev.org/c/openstack/neutron/+/869770
Committed: https://opendev.org/openstack/neutron/commit/ed048638f4ef6a1799a1dcbd8819627b3fa8e75e
Submitter: "Zuul (22348)"
Branch: master

commit ed048638f4ef6a1799a1dcbd8819627b3fa8e75e
Author: Brian Haley <email address hidden>
Date: Tue Jan 10 16:40:29 2023 -0500

Add text to WSGI config guide for debugging

Add "broken pipe" example error message to WSGI guide in
rpc_workers section, could help diagnose agent issues.

Trivialfix

Change-Id: I6e95614bce42124f125be4c23fff0d923ea9ebcc
Closes-bug: #1855919

Changed in neutron:
status:	In Progress → Fix Released

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2023-03-02: Fix included in openstack/neutron 22.0.0.0rc1

#20

This issue was fixed in the openstack/neutron 22.0.0.0rc1 release candidate.

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.