yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1641879] [NEW] No routers created after l3-agent start - error during L3NATAgentWithStateReport.periodic_sync_routers_task

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Tore Anderson <tore@xxxxxx>
Date: Tue, 15 Nov 2016 09:09:47 -0000
Reply-to: Bug 1641879 <1641879@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

After (re)starting the L3 agent, a failure during
L3NATAgentWithStateReport.periodic_sync_routers_task was encountered.
This resulted in a Python traceback being dumped to the log ending with
"TypeError: 'NoneType' object is not iterable". The error repeats every
minute or so. (See below.)

While the error persists, no routers are provisioned by the L3 agent. It
just keeps failing and failing and failing in an seemingly infinite
loop.

The fix/workaround was to remove a random router from the L3 agent
having problems, like so:

$ neutron l3-agent-router-remove <uuid-of-l3-agent-having-problems>
<uuid-of-some-router>

It did not seem to matter exactly which of the many routers scheduled to
run on the problematic L3 agent that was removed in this way. The
removal itself seemed to get rid of the blockage, allowing the L3 agent
to start normal operations shortly after.

Excerpts from l3-agent.log:

2016-11-15 03:14:26.201 2988 INFO neutron.common.config [-] Logging enabled!
2016-11-15 03:14:26.201 2988 INFO neutron.common.config [-] /usr/bin/neutron-l3-agent version 8.3.0
2016-11-15 03:14:26.504 2988 INFO eventlet.wsgi.server [-] (2988) wsgi starting up on http:/var/lib/neutron/keepalived-state-change
2016-11-15 03:14:26.548 2988 INFO neutron.agent.l3.agent [-] Agent has just been revived. Doing a full sync.
2016-11-15 03:14:26.781 2988 INFO neutron.agent.l3.agent [-] L3 agent started
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task [req-97b76ec8-9eb6-4e23-8074-63c889c3e199 - - - - -] Error during L3NATAgentWithStateReport.periodic_sync_routers_task
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task Traceback (most recent call last):
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_service/periodic_task.py", line 220, in run_periodic_tasks
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     task(self, context)
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/neutron/agent/l3/agent.py", line 545, in periodic_sync_routers_task
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     self.fetch_and_sync_all_routers(context, ns_manager)
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/neutron/agent/l3/agent.py", line 556, in fetch_and_sync_all_routers
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     self.plugin_rpc.get_router_ids(context))
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/neutron/agent/l3/agent.py", line 108, in get_router_ids
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     return cctxt.call(context, 'get_router_ids', host=self.host)
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/neutron/common/rpc.py", line 136, in call
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     return self._original_context.call(ctxt, method, **kwargs)
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/client.py", line 158, in call
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     retry=self.retry)
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_messaging/transport.py", line 90, in _send
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     timeout=timeout, retry=retry)
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 470, in send
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     retry=retry)
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 461, in _send
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     raise result
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task TypeError: 'NoneType' object is not iterable
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task Traceback (most recent call last):
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task 
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 138, in _dispatch_and_reply
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     incoming.message))
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task 
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 185, in _dispatch
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     return self._do_dispatch(endpoint, method, ctxt, args)
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task 
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 127, in _do_dispatch
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     result = func(ctxt, **new_args)
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task 
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/neutron/api/rpc/handlers/l3_rpc.py", line 75, in get_router_ids
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     router_ids=None)
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task 
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/neutron/db/l3_agentschedulers_db.py", line 525, in auto_schedule_routers
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     self, context, host, router_ids)
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task 
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/neutron/scheduler/l3_agent_scheduler.py", line 148, in auto_schedule_routers
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     plugin, context, l3_agent)
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task 
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/neutron/scheduler/l3_agent_scheduler.py", line 314, in _schedule_ha_routers_to_addition
al_agent
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     for router in schedulable_routers:
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task 
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task TypeError: 'NoneType' object is not iterable
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task 
2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task 

[ some time pass ]

2016-11-15 03:15:08.152 2988 ERROR oslo_service.periodic_task [req-97b76ec8-9eb6-4e23-8074-63c889c3e199 - - - - -] Error during L3NATAgentWithStateReport.periodic_sync_routers_task
2016-11-15 03:15:08.152 2988 ERROR oslo_service.periodic_task Traceback (most recent call last):
2016-11-15 03:15:08.152 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_service/periodic_task.py", line 220, in run_periodic_tasks
2016-11-15 03:15:08.152 2988 ERROR oslo_service.periodic_task     task(self, context)
[ ... ]

[ "neutron l3-agent-router-remove <l3-agent-uuid> d95d9198-9960-4f2c-
b33f-d6211ef1a8a3" is run]

2016-11-15 03:15:50.441 2988 WARNING neutron.agent.l3.agent [-] Info for router d95d9198-9960-4f2c-b33f-d6211ef1a8a3 was not found. Performing router cleanup
2016-11-15 03:17:23.102 2988 WARNING oslo.service.loopingcall [req-97b76ec8-9eb6-4e23-8074-63c889c3e199 - - - - -] Function 'neutron.service.Service.periodic_tasks' run outlasted interval by
 15.31 sec
2016-11-15 03:17:23.174 2988 INFO oslo_rootwrap.client [-] Spawned new rootwrap daemon process with pid=9015
2016-11-15 03:17:23.634 2988 INFO neutron.agent.l3.ha [-] Router 19258eff-2755-41b8-aefb-1c9b2af991f4 transitioned to backup
[ ... ]

At this point, the L3 agent starts operating normally, creating all the
routers it's scheduled to run and so on.

** Affects: neutron
     Importance: Undecided
         Status: New

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to neutron.
https://bugs.launchpad.net/bugs/1641879

Title:
  No routers created after l3-agent start - error during
  L3NATAgentWithStateReport.periodic_sync_routers_task

Status in neutron:
  New

Bug description:
  After (re)starting the L3 agent, a failure during
  L3NATAgentWithStateReport.periodic_sync_routers_task was encountered.
  This resulted in a Python traceback being dumped to the log ending
  with "TypeError: 'NoneType' object is not iterable". The error repeats
  every minute or so. (See below.)

  While the error persists, no routers are provisioned by the L3 agent.
  It just keeps failing and failing and failing in an seemingly infinite
  loop.

  The fix/workaround was to remove a random router from the L3 agent
  having problems, like so:

  $ neutron l3-agent-router-remove <uuid-of-l3-agent-having-problems>
  <uuid-of-some-router>

  It did not seem to matter exactly which of the many routers scheduled
  to run on the problematic L3 agent that was removed in this way. The
  removal itself seemed to get rid of the blockage, allowing the L3
  agent to start normal operations shortly after.

  Excerpts from l3-agent.log:

  2016-11-15 03:14:26.201 2988 INFO neutron.common.config [-] Logging enabled!
  2016-11-15 03:14:26.201 2988 INFO neutron.common.config [-] /usr/bin/neutron-l3-agent version 8.3.0
  2016-11-15 03:14:26.504 2988 INFO eventlet.wsgi.server [-] (2988) wsgi starting up on http:/var/lib/neutron/keepalived-state-change
  2016-11-15 03:14:26.548 2988 INFO neutron.agent.l3.agent [-] Agent has just been revived. Doing a full sync.
  2016-11-15 03:14:26.781 2988 INFO neutron.agent.l3.agent [-] L3 agent started
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task [req-97b76ec8-9eb6-4e23-8074-63c889c3e199 - - - - -] Error during L3NATAgentWithStateReport.periodic_sync_routers_task
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task Traceback (most recent call last):
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_service/periodic_task.py", line 220, in run_periodic_tasks
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     task(self, context)
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/neutron/agent/l3/agent.py", line 545, in periodic_sync_routers_task
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     self.fetch_and_sync_all_routers(context, ns_manager)
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/neutron/agent/l3/agent.py", line 556, in fetch_and_sync_all_routers
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     self.plugin_rpc.get_router_ids(context))
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/neutron/agent/l3/agent.py", line 108, in get_router_ids
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     return cctxt.call(context, 'get_router_ids', host=self.host)
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/neutron/common/rpc.py", line 136, in call
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     return self._original_context.call(ctxt, method, **kwargs)
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/client.py", line 158, in call
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     retry=self.retry)
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_messaging/transport.py", line 90, in _send
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     timeout=timeout, retry=retry)
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 470, in send
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     retry=retry)
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py", line 461, in _send
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     raise result
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task TypeError: 'NoneType' object is not iterable
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task Traceback (most recent call last):
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task 
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 138, in _dispatch_and_reply
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     incoming.message))
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task 
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 185, in _dispatch
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     return self._do_dispatch(endpoint, method, ctxt, args)
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task 
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_messaging/rpc/dispatcher.py", line 127, in _do_dispatch
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     result = func(ctxt, **new_args)
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task 
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/neutron/api/rpc/handlers/l3_rpc.py", line 75, in get_router_ids
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     router_ids=None)
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task 
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/neutron/db/l3_agentschedulers_db.py", line 525, in auto_schedule_routers
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     self, context, host, router_ids)
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task 
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/neutron/scheduler/l3_agent_scheduler.py", line 148, in auto_schedule_routers
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     plugin, context, l3_agent)
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task 
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/neutron/scheduler/l3_agent_scheduler.py", line 314, in _schedule_ha_routers_to_addition
  al_agent
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task     for router in schedulable_routers:
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task 
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task TypeError: 'NoneType' object is not iterable
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task 
  2016-11-15 03:14:28.297 2988 ERROR oslo_service.periodic_task 

  [ some time pass ]

  2016-11-15 03:15:08.152 2988 ERROR oslo_service.periodic_task [req-97b76ec8-9eb6-4e23-8074-63c889c3e199 - - - - -] Error during L3NATAgentWithStateReport.periodic_sync_routers_task
  2016-11-15 03:15:08.152 2988 ERROR oslo_service.periodic_task Traceback (most recent call last):
  2016-11-15 03:15:08.152 2988 ERROR oslo_service.periodic_task   File "/usr/lib/python2.7/site-packages/oslo_service/periodic_task.py", line 220, in run_periodic_tasks
  2016-11-15 03:15:08.152 2988 ERROR oslo_service.periodic_task     task(self, context)
  [ ... ]

  [ "neutron l3-agent-router-remove <l3-agent-uuid> d95d9198-9960-4f2c-
  b33f-d6211ef1a8a3" is run]

  2016-11-15 03:15:50.441 2988 WARNING neutron.agent.l3.agent [-] Info for router d95d9198-9960-4f2c-b33f-d6211ef1a8a3 was not found. Performing router cleanup
  2016-11-15 03:17:23.102 2988 WARNING oslo.service.loopingcall [req-97b76ec8-9eb6-4e23-8074-63c889c3e199 - - - - -] Function 'neutron.service.Service.periodic_tasks' run outlasted interval by
   15.31 sec
  2016-11-15 03:17:23.174 2988 INFO oslo_rootwrap.client [-] Spawned new rootwrap daemon process with pid=9015
  2016-11-15 03:17:23.634 2988 INFO neutron.agent.l3.ha [-] Router 19258eff-2755-41b8-aefb-1c9b2af991f4 transitioned to backup
  [ ... ]

  At this point, the L3 agent starts operating normally, creating all
  the routers it's scheduled to run and so on.

To manage notifications about this bug go to:
https://bugs.launchpad.net/neutron/+bug/1641879/+subscriptions
Follow ups

[Bug 1641879] Re: No routers created after l3-agent start - error during L3NATAgentWithStateReport.periodic_sync_routers_task
From: OpenStack Infra, 2016-11-25