2022-05-11 21:24:09.187 951 DEBUG neutron.agent.l3.agent [req-c0d9fa60-e145-4872-ad23-d3bc27453dc7 181b8917423847fba4ee2aab5100497d 884742392e414877a102240387f46823 - - -] Got routers updated notification :['41fcd10b-7db5-45d9-b23c-e22f34c45eec'] routers_updated /var/lib/kolla/venv/lib/python3.8/site-packages/neutron/agent/l3/agent.py:586
2022-05-11 21:24:09.189 951 INFO neutron.agent.l3.agent [-] Starting processing update 41fcd10b-7db5-45d9-b23c-e22f34c45eec, action 3, priority 1, update_id 0d6f9a8e-05d2-4150-ae99-0078c123c068. Wait time elapsed: 0.001
2022-05-11 21:24:09.190 951 INFO neutron.agent.l3.agent [-] Starting router update for 41fcd10b-7db5-45d9-b23c-e22f34c45eec, action 3, priority 1, update_id 0d6f9a8e-05d2-4150-ae99-0078c123c068. Wait time elapsed: 0.002
2022-05-11 21:24:09.190 951 DEBUG neutron.common.utils [-] Time-cost: call f62f7e77-a67a-40dd-bb67-9aedb45f0240 function get_routers start wrapper /var/lib/kolla/venv/lib/python3.8/site-packages/neutron/common/utils.py:934
2022-05-11 21:24:10.699 951 DEBUG neutron.common.utils [-] Time-cost: call f62f7e77-a67a-40dd-bb67-9aedb45f0240 function get_routers took 1.509s seconds to run wrapper /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_utils/timeutils.py:386
2022-05-11 21:24:10.700 951 DEBUG neutron.agent.l3.agent [-] Router 41fcd10b-7db5-45d9-b23c-e22f34c45eec info in cache, will do the router update action. _process_router_if_compatible /var/lib/kolla/venv/lib/python3.8/site-packages/neutron/agent/l3/agent.py:644
2022-05-11 21:24:10.700 951 DEBUG neutron_lib.callbacks.manager [-] Notify callbacks [] for router, before_update _notify_loop /var/lib/kolla/venv/lib/python3.8/site-packages/neutron_lib/callbacks/manager.py:192
2022-05-11 21:24:10.773 951 DEBUG neutron.agent.l3.router_info [-] Process updates, router 41fcd10b-7db5-45d9-b23c-e22f34c45eec process /var/lib/kolla/venv/lib/python3.8/site-packages/neutron/agent/l3/router_info.py:1307
2022-05-11 21:24:10.795 951 DEBUG oslo_concurrency.lockutils [-] Lock "l3-agent-pd" acquired by "neutron.agent.linux.pd.PrefixDelegation.sync_router" :: waited 0.000s inner /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:355
2022-05-11 21:24:10.796 951 DEBUG oslo_concurrency.lockutils [-] Lock "l3-agent-pd" released by "neutron.agent.linux.pd.PrefixDelegation.sync_router" :: held 0.000s inner /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:367
2022-05-11 21:24:10.796 951 DEBUG oslo_concurrency.lockutils [-] Acquired lock "port-lock-fip-6636b4e5-16e2-482b-a0a7-5897ab0776c4-fg-0f0c96ae-7a" lock /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:266
2022-05-11 21:24:10.847 951 DEBUG oslo_concurrency.lockutils [-] Releasing lock "port-lock-fip-6636b4e5-16e2-482b-a0a7-5897ab0776c4-fg-0f0c96ae-7a" lock /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:282
2022-05-11 21:24:10.859 951 DEBUG oslo_concurrency.lockutils [-] Acquired lock "router-lock-ns-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" lock /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:266
2022-05-11 21:24:10.859 951 DEBUG neutron.common.coordination [-] Lock "router-lock-ns-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" acquired by "process_external" :: waited 0.000s _synchronized /var/lib/kolla/venv/lib/python3.8/site-packages/neutron/common/coordination.py:73
2022-05-11 21:24:10.897 951 DEBUG oslo_concurrency.lockutils [-] Acquired lock "iptables-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" lock /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:266
2022-05-11 21:24:10.898 951 DEBUG oslo_concurrency.lockutils [-] Acquired external semaphore "iptables-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" lock /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:272
2022-05-11 21:24:10.943 951 DEBUG neutron.agent.linux.iptables_manager [-] IPTablesManager.apply completed with success. 6 iptables commands were issued _apply_synchronized /var/lib/kolla/venv/lib/python3.8/site-packages/neutron/agent/linux/iptables_manager.py:625
2022-05-11 21:24:10.944 951 DEBUG oslo_concurrency.lockutils [-] Releasing lock "iptables-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" lock /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:282
2022-05-11 21:24:11.028 951 DEBUG oslo_concurrency.lockutils [-] Releasing lock "router-lock-ns-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" lock /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:282
2022-05-11 21:24:11.029 951 DEBUG neutron.common.coordination [-] Lock "router-lock-ns-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" released by "process_external" :: held 0.170s _synchronized /var/lib/kolla/venv/lib/python3.8/site-packages/neutron/common/coordination.py:85
2022-05-11 21:24:11.029 951 DEBUG oslo_concurrency.lockutils [-] Acquired lock "router-lock-ns-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" lock /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:266
2022-05-11 21:24:11.029 951 DEBUG neutron.common.coordination [-] Lock "router-lock-ns-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" acquired by "process_address_scope" :: waited 0.000s _synchronized /var/lib/kolla/venv/lib/python3.8/site-packages/neutron/common/coordination.py:73
2022-05-11 21:24:11.057 951 DEBUG oslo_concurrency.lockutils [-] Acquired lock "iptables-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" lock /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:266
2022-05-11 21:24:11.057 951 DEBUG oslo_concurrency.lockutils [-] Acquired external semaphore "iptables-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" lock /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:272
2022-05-11 21:24:11.083 951 DEBUG neutron.agent.linux.iptables_manager [-] IPTablesManager.apply completed with success. 0 iptables commands were issued _apply_synchronized /var/lib/kolla/venv/lib/python3.8/site-packages/neutron/agent/linux/iptables_manager.py:625
2022-05-11 21:24:11.083 951 DEBUG oslo_concurrency.lockutils [-] Releasing lock "iptables-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" lock /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:282
2022-05-11 21:24:11.083 951 DEBUG oslo_concurrency.lockutils [-] Releasing lock "router-lock-ns-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" lock /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:282
2022-05-11 21:24:11.083 951 DEBUG neutron.common.coordination [-] Lock "router-lock-ns-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" released by "process_address_scope" :: held 0.054s _synchronized /var/lib/kolla/venv/lib/python3.8/site-packages/neutron/common/coordination.py:85
2022-05-11 21:24:11.084 951 DEBUG neutron.agent.l3.router_info [-] Removed route entry is '{'destination': '192.168.25.0/24', 'nexthop': '10.50.51.1'}' routes_updated /var/lib/kolla/venv/lib/python3.8/site-packages/neutron/agent/l3/router_info.py:245
2022-05-11 21:24:11.107 951 DEBUG neutron_lib.callbacks.manager [-] Notify callbacks ['neutron.agent.metadata.driver.after_router_updated-8778777282865', 'neutron.agent.linux.pd.update_router-8778777281118'] for router, after_update _notify_loop /var/lib/kolla/venv/lib/python3.8/site-packages/neutron_lib/callbacks/manager.py:192
2022-05-11 21:24:11.107 951 DEBUG oslo_concurrency.lockutils [-] Lock "l3-agent-pd" acquired by "neutron.agent.linux.pd.update_router" :: waited 0.000s inner /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:355
2022-05-11 21:24:11.108 951 DEBUG oslo_concurrency.lockutils [-] Lock "l3-agent-pd" released by "neutron.agent.linux.pd.update_router" :: held 0.000s inner /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:367
2022-05-11 21:24:11.108 951 DEBUG neutron.agent.l3.l3_agent_extensions_manager [-] L3 agent extension(s) finished router 41fcd10b-7db5-45d9-b23c-e22f34c45eec update action. update_router /var/lib/kolla/venv/lib/python3.8/site-packages/neutron/agent/l3/l3_agent_extensions_manager.py:63
2022-05-11 21:24:11.108 951 INFO neutron.agent.l3.agent [-] Finished a router update for 41fcd10b-7db5-45d9-b23c-e22f34c45eec, update_id 0d6f9a8e-05d2-4150-ae99-0078c123c068. Time elapsed: 1.919
2022-05-11 21:24:22.707 951 DEBUG oslo_service.periodic_task [req-85c87e55-5d28-44a5-ba20-282ac842c18a - - - - -] Running periodic task L3NATAgentWithStateReport.periodic_sync_routers_task run_periodic_tasks /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_service/periodic_task.py:210
2022-05-11 21:24:36.777 951 DEBUG neutron.agent.l3.agent [req-9e76cefe-be04-426c-a8b9-6ca2d3788417 181b8917423847fba4ee2aab5100497d 884742392e414877a102240387f46823 - - -] Got routers updated notification :['41fcd10b-7db5-45d9-b23c-e22f34c45eec'] routers_updated /var/lib/kolla/venv/lib/python3.8/site-packages/neutron/agent/l3/agent.py:586
2022-05-11 21:24:36.779 951 INFO neutron.agent.l3.agent [-] Starting processing update 41fcd10b-7db5-45d9-b23c-e22f34c45eec, action 3, priority 1, update_id 22d78d78-ecc7-4173-a354-1388ab90e883. Wait time elapsed: 0.001
2022-05-11 21:24:36.779 951 INFO neutron.agent.l3.agent [-] Starting router update for 41fcd10b-7db5-45d9-b23c-e22f34c45eec, action 3, priority 1, update_id 22d78d78-ecc7-4173-a354-1388ab90e883. Wait time elapsed: 0.001
2022-05-11 21:24:36.780 951 DEBUG neutron.common.utils [-] Time-cost: call f62f7e77-a67a-40dd-bb67-9aedb45f0240 function get_routers start wrapper /var/lib/kolla/venv/lib/python3.8/site-packages/neutron/common/utils.py:934
2022-05-11 21:24:38.201 951 DEBUG neutron.common.utils [-] Time-cost: call f62f7e77-a67a-40dd-bb67-9aedb45f0240 function get_routers took 1.421s seconds to run wrapper /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_utils/timeutils.py:386
2022-05-11 21:24:38.202 951 DEBUG neutron.agent.l3.agent [-] Router 41fcd10b-7db5-45d9-b23c-e22f34c45eec info in cache, will do the router update action. _process_router_if_compatible /var/lib/kolla/venv/lib/python3.8/site-packages/neutron/agent/l3/agent.py:644
2022-05-11 21:24:38.202 951 DEBUG neutron_lib.callbacks.manager [-] Notify callbacks [] for router, before_update _notify_loop /var/lib/kolla/venv/lib/python3.8/site-packages/neutron_lib/callbacks/manager.py:192
2022-05-11 21:24:38.296 951 DEBUG neutron.agent.l3.router_info [-] Process updates, router 41fcd10b-7db5-45d9-b23c-e22f34c45eec process /var/lib/kolla/venv/lib/python3.8/site-packages/neutron/agent/l3/router_info.py:1307
2022-05-11 21:24:38.319 951 DEBUG oslo_concurrency.lockutils [-] Lock "l3-agent-pd" acquired by "neutron.agent.linux.pd.PrefixDelegation.sync_router" :: waited 0.000s inner /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:355
2022-05-11 21:24:38.320 951 DEBUG oslo_concurrency.lockutils [-] Lock "l3-agent-pd" released by "neutron.agent.linux.pd.PrefixDelegation.sync_router" :: held 0.001s inner /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:367
2022-05-11 21:24:38.321 951 DEBUG oslo_concurrency.lockutils [-] Acquired lock "port-lock-fip-6636b4e5-16e2-482b-a0a7-5897ab0776c4-fg-0f0c96ae-7a" lock /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:266
2022-05-11 21:24:38.375 951 DEBUG oslo_concurrency.lockutils [-] Releasing lock "port-lock-fip-6636b4e5-16e2-482b-a0a7-5897ab0776c4-fg-0f0c96ae-7a" lock /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:282
2022-05-11 21:24:38.389 951 DEBUG oslo_concurrency.lockutils [-] Acquired lock "router-lock-ns-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" lock /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:266
2022-05-11 21:24:38.390 951 DEBUG neutron.common.coordination [-] Lock "router-lock-ns-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" acquired by "process_external" :: waited 0.001s _synchronized /var/lib/kolla/venv/lib/python3.8/site-packages/neutron/common/coordination.py:73
2022-05-11 21:24:38.411 951 DEBUG oslo_concurrency.lockutils [-] Lock "_check_child_processes" acquired by "neutron.agent.linux.external_process.ProcessMonitor._check_child_processes" :: waited 0.000s inner /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:355
2022-05-11 21:24:38.413 951 DEBUG oslo_concurrency.lockutils [-] Lock "_check_child_processes" released by "neutron.agent.linux.external_process.ProcessMonitor._check_child_processes" :: held 0.001s inner /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:367
2022-05-11 21:24:38.413 951 DEBUG oslo_concurrency.lockutils [-] Lock "_check_child_processes" acquired by "neutron.agent.linux.external_process.ProcessMonitor._check_child_processes" :: waited 0.001s inner /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:355
2022-05-11 21:24:38.413 951 DEBUG oslo_concurrency.lockutils [-] Lock "_check_child_processes" released by "neutron.agent.linux.external_process.ProcessMonitor._check_child_processes" :: held 0.000s inner /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:367
2022-05-11 21:24:38.433 951 DEBUG oslo_concurrency.lockutils [-] Acquired lock "iptables-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" lock /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:266
2022-05-11 21:24:38.434 951 DEBUG oslo_concurrency.lockutils [-] Acquired external semaphore "iptables-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" lock /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:272
2022-05-11 21:24:38.467 951 DEBUG neutron.agent.linux.iptables_manager [-] IPTablesManager.apply completed with success. 0 iptables commands were issued _apply_synchronized /var/lib/kolla/venv/lib/python3.8/site-packages/neutron/agent/linux/iptables_manager.py:625
2022-05-11 21:24:38.467 951 DEBUG oslo_concurrency.lockutils [-] Releasing lock "iptables-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" lock /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:282
2022-05-11 21:24:38.554 951 DEBUG oslo_concurrency.lockutils [-] Releasing lock "router-lock-ns-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" lock /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:282
2022-05-11 21:24:38.555 951 DEBUG neutron.common.coordination [-] Lock "router-lock-ns-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" released by "process_external" :: held 0.165s _synchronized /var/lib/kolla/venv/lib/python3.8/site-packages/neutron/common/coordination.py:85
2022-05-11 21:24:38.555 951 DEBUG oslo_concurrency.lockutils [-] Acquired lock "router-lock-ns-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" lock /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:266
2022-05-11 21:24:38.556 951 DEBUG neutron.common.coordination [-] Lock "router-lock-ns-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" acquired by "process_address_scope" :: waited 0.000s _synchronized /var/lib/kolla/venv/lib/python3.8/site-packages/neutron/common/coordination.py:73
2022-05-11 21:24:38.573 951 DEBUG oslo_concurrency.lockutils [-] Acquired lock "iptables-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" lock /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:266
2022-05-11 21:24:38.574 951 DEBUG oslo_concurrency.lockutils [-] Acquired external semaphore "iptables-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" lock /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:272
2022-05-11 21:24:38.604 951 DEBUG neutron.agent.linux.iptables_manager [-] IPTablesManager.apply completed with success. 0 iptables commands were issued _apply_synchronized /var/lib/kolla/venv/lib/python3.8/site-packages/neutron/agent/linux/iptables_manager.py:625
2022-05-11 21:24:38.604 951 DEBUG oslo_concurrency.lockutils [-] Releasing lock "iptables-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" lock /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:282
2022-05-11 21:24:38.604 951 DEBUG oslo_concurrency.lockutils [-] Releasing lock "router-lock-ns-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" lock /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:282
2022-05-11 21:24:38.604 951 DEBUG neutron.common.coordination [-] Lock "router-lock-ns-qrouter-41fcd10b-7db5-45d9-b23c-e22f34c45eec" released by "process_address_scope" :: held 0.049s _synchronized /var/lib/kolla/venv/lib/python3.8/site-packages/neutron/common/coordination.py:85
2022-05-11 21:24:38.605 951 DEBUG neutron.agent.l3.router_info [-] Added route entry is '{'destination': '192.168.25.0/24', 'nexthop': '10.50.51.1'}' routes_updated /var/lib/kolla/venv/lib/python3.8/site-packages/neutron/agent/l3/router_info.py:251
2022-05-11 21:24:38.640 951 DEBUG neutron_lib.callbacks.manager [-] Notify callbacks ['neutron.agent.metadata.driver.after_router_updated-8778777282865', 'neutron.agent.linux.pd.update_router-8778777281118'] for router, after_update _notify_loop /var/lib/kolla/venv/lib/python3.8/site-packages/neutron_lib/callbacks/manager.py:192
2022-05-11 21:24:38.641 951 DEBUG oslo_concurrency.lockutils [-] Lock "l3-agent-pd" acquired by "neutron.agent.linux.pd.update_router" :: waited 0.000s inner /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:355
2022-05-11 21:24:38.641 951 DEBUG oslo_concurrency.lockutils [-] Lock "l3-agent-pd" released by "neutron.agent.linux.pd.update_router" :: held 0.000s inner /var/lib/kolla/venv/lib/python3.8/site-packages/oslo_concurrency/lockutils.py:367
2022-05-11 21:24:38.641 951 DEBUG neutron.agent.l3.l3_agent_extensions_manager [-] L3 agent extension(s) finished router 41fcd10b-7db5-45d9-b23c-e22f34c45eec update action. update_router /var/lib/kolla/venv/lib/python3.8/site-packages/neutron/agent/l3/l3_agent_extensions_manager.py:63
2022-05-11 21:24:38.642 951 INFO neutron.agent.l3.agent [-] Finished a router update for 41fcd10b-7db5-45d9-b23c-e22f34c45eec, update_id 22d78d78-ecc7-4173-a354-1388ab90e883. Time elapsed: 1.863