yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1651368] [NEW] Dhcpagent not efficient during initialization process

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Bertrand Lallau <bertrand.lallau@xxxxxxxxx>
Date: Tue, 20 Dec 2016 09:43:16 -0000
Reply-to: Bug 1651368 <1651368@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

During DhcpAgent startup procedure all networks initialization will be done twice:
 * Killing old dnsmasq processes
 * set and configure all TAP interfaces
 * building all Dnsmasq config files (lease and host files)
 * launching dnsmasq processes
This is really inefficient and can be strange in case of namespaces monitoring.


The following Dhcpagent traces show the procedure describe just above (logs have been cleanup to show only relevant informations)


2016-12-20 09:02:42.200 DEBUG neutron.openstack.common.service [req-b0a2772 None None] ******************************************************************************** log_opt_values /usr/lib/python2.7/dist-packages/oslo_config/cfg.py:2197
2016-12-20 09:02:42.214 INFO neutron.agent.dhcp.agent [-] Synchronizing state
2016-12-20 09:02:43.262 DEBUG neutron.agent.dhcp.agent [-] Calling driver for network: 5be9fe58-0790-4342-9182-172438e8e0bc action: enable call_driver /usr/lib/python2.7/dist-packages/neutron/agent/dhcp/agent.py:106
2016-12-20 09:02:43.314 DEBUG neutron.agent.dhcp.agent [-] Calling driver for network: f2a73fc1-6a93-4822-aa45-3333b789d50d action: enable call_driver /usr/lib/python2.7/dist-packages/neutron/agent/dhcp/agent.py:106
Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'kill', '-9', '24540']
2016-12-20 09:02:43.441 DEBUG neutron.agent.linux.utils [-] Unable to access /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/pid get_value_from_file /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:222
Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'kill', '-9', '24542']
2016-12-20 09:02:43.459 DEBUG neutron.agent.linux.utils [-] Unable to access /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/pid get_value_from_file /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:222
Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', 'link', 'set', 'tap5c7f794d-08', 'up']
Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', 'link', 'set', 'tap995da463-09', 'up']
Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', 'addr', 'show', 'tap5c7f794d-08', 'permanent', 'scope', 'global']
Stdout: 32: tap5c7f794d-08: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default
    link/ether fa:16:3e:6b:cb:29 brd ff:ff:ff:ff:ff:ff
    inet 20.0.0.36/24 brd 20.0.0.255 scope global tap5c7f794d-08
       valid_lft forever preferred_lft forever
    inet 169.254.169.254/16 brd 169.254.255.255 scope global tap5c7f794d-08
       valid_lft forever preferred_lft forever

Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', 'addr', 'show', 'tap995da463-09', 'permanent', 'scope', 'global']
Stdout: 35: tap995da463-09: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default
    link/ether fa:16:3e:49:6e:68 brd ff:ff:ff:ff:ff:ff
    inet 20.0.1.36/24 brd 20.0.1.255 scope global tap995da463-09
       valid_lft forever preferred_lft forever
    inet 169.254.169.254/16 brd 169.254.255.255 scope global tap995da463-09
       valid_lft forever preferred_lft forever

Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', '-4', 'route', 'list', 'dev', 'tap995da463-09', 'scope', 'link']
Stdout: 20.0.1.0/24  proto kernel  src 20.0.1.36
169.254.0.0/16  proto kernel  src 169.254.169.254

Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', '-4', 'route', 'list', 'dev', 'tap5c7f794d-08', 'scope', 'link']
Stdout: 20.0.0.0/24  proto kernel  src 20.0.0.36
169.254.0.0/16  proto kernel  src 169.254.169.254

Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', '-6', 'route', 'list', 'dev', 'tap995da463-09', 'scope', 'link']
Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', '-6', 'route', 'list', 'dev', 'tap5c7f794d-08', 'scope', 'link']
Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', 'route', 'list', 'dev', 'tap995da463-09']
Stdout: 20.0.1.0/24  proto kernel  scope link  src 20.0.1.36
169.254.0.0/16  proto kernel  scope link  src 169.254.169.254
2016-12-20 09:02:44.154 DEBUG neutron.agent.linux.dhcp [-] Building initial lease file: /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/leases _output_init_lease_file /home/T0125936/work/curr/neutron/neutron/agent/linux/dhcp.py:480
2016-12-20 09:02:44.155 DEBUG neutron.agent.linux.dhcp [-] Done building initial lease file /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/leases with contents:
1482310964 fa:16:3e:49:6e:68 20.0.1.36 * *
1482310964 fa:16:3e:81:6c:f3 20.0.1.35 * *
 _output_init_lease_file /home/T0125936/work/curr/neutron/neutron/agent/linux/dhcp.py:507
2016-12-20 09:02:44.156 DEBUG neutron.agent.linux.dhcp [-] Building host file: /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/host _output_hosts_file neutron/agent/linux/dhcp.py:538
2016-12-20 09:02:44.156 DEBUG neutron.agent.linux.dhcp [-] Done building host file /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/host with contents:
fa:16:3e:49:6e:68,host-20-0-1-36.openstacklocal,20.0.1.36
fa:16:3e:81:6c:f3,host-20-0-1-35.openstacklocal,20.0.1.35
 _output_hosts_file neutron/agent/linux/dhcp.py:567
Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', 'route', 'list', 'dev', 'tap5c7f794d-08']
Stdout: 20.0.0.0/24  proto kernel  scope link  src 20.0.0.36
169.254.0.0/16  proto kernel  scope link  src 169.254.169.254

Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
2016-12-20 09:02:44.173 DEBUG neutron.agent.linux.dhcp [-] Building initial lease file: /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/leases _output_init_lease_file neutron/agent/linux/dhcp.py:480
2016-12-20 09:02:44.173 DEBUG neutron.agent.linux.dhcp [-] Done building initial lease file /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/leases with contents:
1482310964 fa:16:3e:6b:cb:29 20.0.0.36 * *
1482310964 fa:16:3e:74:32:29 20.0.0.35 * *
 _output_init_lease_file neutron/agent/linux/dhcp.py:507
2016-12-20 09:02:44.174 DEBUG neutron.agent.linux.dhcp [-] Building host file: /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/host _output_hosts_file neutron/agent/linux/dhcp.py:538
2016-12-20 09:02:44.175 DEBUG neutron.agent.linux.dhcp [-] Done building host file /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/host with contents:
fa:16:3e:6b:cb:29,host-20-0-0-36.openstacklocal,20.0.0.36
fa:16:3e:74:32:29,host-20-0-0-35.openstacklocal,20.0.0.35
 _output_hosts_file neutron/agent/linux/dhcp.py:567
Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', 'addr', 'show', 'tap995da463-09']
Stdout: 35: tap995da463-09: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default
    link/ether fa:16:3e:49:6e:68 brd ff:ff:ff:ff:ff:ff
    inet 20.0.1.36/24 brd 20.0.1.255 scope global tap995da463-09
       valid_lft forever preferred_lft forever
    inet 169.254.169.254/16 brd 169.254.255.255 scope global tap995da463-09
       valid_lft forever preferred_lft forever
    inet6 fe80::f816:3eff:fe49:6e68/64 scope link
       valid_lft forever preferred_lft forever

Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
2016-12-20 09:02:44.293 DEBUG neutron.agent.linux.utils [-] Unable to access /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/pid get_value_from_file /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:222
Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', 'addr', 'show', 'tap5c7f794d-08']
Stdout: 32: tap5c7f794d-08: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default
    link/ether fa:16:3e:6b:cb:29 brd ff:ff:ff:ff:ff:ff
    inet 20.0.0.36/24 brd 20.0.0.255 scope global tap5c7f794d-08
       valid_lft forever preferred_lft forever
    inet 169.254.169.254/16 brd 169.254.255.255 scope global tap5c7f794d-08
       valid_lft forever preferred_lft forever
    inet6 fe80::f816:3eff:fe6b:cb29/64 scope link
       valid_lft forever preferred_lft forever

Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
2016-12-20 09:02:44.313 DEBUG neutron.agent.linux.utils [-] Unable to access /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/pid get_value_from_file /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:222
Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'dnsmasq', '--no-hosts', '--no-resolv', '--strict-order', '--bind-interfaces', '--interface=tap995da463-09', '--except-interface=lo', '--pid-file=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/pid', '--dhcp-hostsfile=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/host', '--addn-hosts=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/addn_hosts', '--dhcp-optsfile=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/opts', '--dhcp-leasefile=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/leases', '--dhcp-range=set:tag0,20.0.1.0,static,86400s', '--dhcp-lease-max=256', '--conf-file=/etc/neutron/dnsmasq.conf', '--domain=openstacklocal']
Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'dnsmasq', '--no-hosts', '--no-resolv', '--strict-order', '--bind-interfaces', '--interface=tap5c7f794d-08', '--except-interface=lo', '--pid-file=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/pid', '--dhcp-hostsfile=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/host', '--addn-hosts=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/addn_hosts', '--dhcp-optsfile=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/opts', '--dhcp-leasefile=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/leases', '--dhcp-range=set:tag0,20.0.0.0,static,86400s', '--dhcp-lease-max=256', '--conf-file=/etc/neutron/dnsmasq.conf', '--domain=openstacklocal']
2016-12-20 09:02:44.441 INFO neutron.agent.dhcp.agent [-] Synchronizing state complete

2016-12-20 09:02:44.453 DEBUG oslo_concurrency.lockutils [req-555b9ae None None] Lock "dhcp-agent" acquired by "sync_state" :: waited 2.081s inner /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:444
2016-12-20 09:02:44.453 INFO neutron.agent.dhcp.agent [req-555b9ae None None] Synchronizing state
2016-12-20 09:02:44.479 INFO neutron.agent.dhcp.agent [-] DHCP agent started
2016-12-20 09:02:44.696 DEBUG neutron.agent.dhcp.agent [-] Calling driver for network: 5be9fe58-0790-4342-9182-172438e8e0bc action: enable call_driver /usr/lib/python2.7/dist-packages/neutron/agent/dhcp/agent.py:106
2016-12-20 09:02:44.704 DEBUG neutron.agent.dhcp.agent [-] Calling driver for network: f2a73fc1-6a93-4822-aa45-3333b789d50d action: enable call_driver /usr/lib/python2.7/dist-packages/neutron/agent/dhcp/agent.py:106
Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'kill', '-9', '24936']
2016-12-20 09:02:44.820 DEBUG neutron.agent.linux.utils [-] Unable to access /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/pid get_value_from_file /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:222
2016-12-20 09:02:44.836 DEBUG neutron.agent.linux.utils [-] Unable to access /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/pid get_value_from_file /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:222
Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', 'link', 'set', 'tap5c7f794d-08', 'up']
2016-12-20 09:02:45.126 DEBUG neutron.agent.linux.dhcp [-] Reusing existing device: tap5c7f794d-08. setup neutron/agent/linux/dhcp.py:1009
Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', 'link', 'set', 'tap995da463-09', 'up']
2016-12-20 09:02:45.192 DEBUG neutron.agent.linux.dhcp [-] Reusing existing device: tap995da463-09. setup neutron/agent/linux/dhcp.py:1009
Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', 'addr', 'show', 'tap5c7f794d-08', 'permanent', 'scope', 'global']
Stdout: 32: tap5c7f794d-08: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default
    link/ether fa:16:3e:6b:cb:29 brd ff:ff:ff:ff:ff:ff
    inet 20.0.0.36/24 brd 20.0.0.255 scope global tap5c7f794d-08
       valid_lft forever preferred_lft forever
    inet 169.254.169.254/16 brd 169.254.255.255 scope global tap5c7f794d-08
       valid_lft forever preferred_lft forever

Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
2016-12-20 09:02:45.386 DEBUG neutron.agent.linux.utils [-]
Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', 'addr', 'show', 'tap995da463-09', 'permanent', 'scope', 'global']
Stdout: 35: tap995da463-09: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default
    link/ether fa:16:3e:49:6e:68 brd ff:ff:ff:ff:ff:ff
    inet 20.0.1.36/24 brd 20.0.1.255 scope global tap995da463-09
       valid_lft forever preferred_lft forever
    inet 169.254.169.254/16 brd 169.254.255.255 scope global tap995da463-09
       valid_lft forever preferred_lft forever

Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', '-4', 'route', 'list', 'dev', 'tap5c7f794d-08', 'scope', 'link']
Stdout: 20.0.0.0/24  proto kernel  src 20.0.0.36
169.254.0.0/16  proto kernel  src 169.254.169.254

Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', '-4', 'route', 'list', 'dev', 'tap995da463-09', 'scope', 'link']
Stdout: 20.0.1.0/24  proto kernel  src 20.0.1.36
169.254.0.0/16  proto kernel  src 169.254.169.254

Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', '-6', 'route', 'list', 'dev', 'tap5c7f794d-08', 'scope', 'link']
Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', '-6', 'route', 'list', 'dev', 'tap995da463-09', 'scope', 'link']
Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', 'route', 'list', 'dev', 'tap5c7f794d-08']
Stdout: 20.0.0.0/24  proto kernel  scope link  src 20.0.0.36
169.254.0.0/16  proto kernel  scope link  src 169.254.169.254

Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
2016-12-20 09:02:45.862 DEBUG neutron.agent.linux.dhcp [-] Building initial lease file: /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/leases _output_init_lease_file neutron/agent/linux/dhcp.py:480
2016-12-20 09:02:45.863 DEBUG neutron.agent.linux.dhcp [-] Done building initial lease file /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/leases with contents:
1482310965 fa:16:3e:6b:cb:29 20.0.0.36 * *
1482310965 fa:16:3e:74:32:29 20.0.0.35 * *
 _output_init_lease_file neutron/agent/linux/dhcp.py:507
2016-12-20 09:02:45.865 DEBUG neutron.agent.linux.dhcp [-] Building host file: /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/host _output_hosts_file neutron/agent/linux/dhcp.py:538
2016-12-20 09:02:45.874 DEBUG neutron.agent.linux.dhcp [-] Done building host file /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/host with contents:
fa:16:3e:6b:cb:29,host-20-0-0-36.openstacklocal,20.0.0.36
fa:16:3e:74:32:29,host-20-0-0-35.openstacklocal,20.0.0.35
 _output_hosts_file neutron/agent/linux/dhcp.py:567
Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', 'route', 'list', 'dev', 'tap995da463-09']
Exit code: 0
Stdin:
Stdout: 20.0.1.0/24  proto kernel  scope link  src 20.0.1.36
169.254.0.0/16  proto kernel  scope link  src 169.254.169.254

Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
2016-12-20 09:02:45.971 DEBUG neutron.agent.linux.dhcp [-] Building initial lease file: /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/leases _output_init_lease_file neutron/agent/linux/dhcp.py:480
2016-12-20 09:02:45.977 DEBUG neutron.agent.linux.dhcp [-] Done building initial lease file /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/leases with contents:
1482310965 fa:16:3e:49:6e:68 20.0.1.36 * *
1482310965 fa:16:3e:81:6c:f3 20.0.1.35 * *
 _output_init_lease_file neutron/agent/linux/dhcp.py:507
2016-12-20 09:02:45.978 DEBUG neutron.agent.linux.dhcp [-] Building host file: /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/host _output_hosts_file neutron/agent/linux/dhcp.py:538
2016-12-20 09:02:45.986 DEBUG neutron.agent.linux.dhcp [-] Done building host file /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/host with contents:
fa:16:3e:49:6e:68,host-20-0-1-36.openstacklocal,20.0.1.36
fa:16:3e:81:6c:f3,host-20-0-1-35.openstacklocal,20.0.1.35
 _output_hosts_file neutron/agent/linux/dhcp.py:567
Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', 'addr', 'show', 'tap5c7f794d-08']
Stdout: 32: tap5c7f794d-08: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default
    link/ether fa:16:3e:6b:cb:29 brd ff:ff:ff:ff:ff:ff
    inet 20.0.0.36/24 brd 20.0.0.255 scope global tap5c7f794d-08
       valid_lft forever preferred_lft forever
    inet 169.254.169.254/16 brd 169.254.255.255 scope global tap5c7f794d-08
       valid_lft forever preferred_lft forever
    inet6 fe80::f816:3eff:fe6b:cb29/64 scope link
       valid_lft forever preferred_lft forever

Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
2016-12-20 09:02:46.107 DEBUG neutron.agent.linux.utils [-] Unable to access /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/pid get_value_from_file /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:222
Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', 'addr', 'show', 'tap995da463-09']
Stdout: 35: tap995da463-09: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default
    link/ether fa:16:3e:49:6e:68 brd ff:ff:ff:ff:ff:ff
    inet 20.0.1.36/24 brd 20.0.1.255 scope global tap995da463-09
       valid_lft forever preferred_lft forever
    inet 169.254.169.254/16 brd 169.254.255.255 scope global tap995da463-09
       valid_lft forever preferred_lft forever
    inet6 fe80::f816:3eff:fe49:6e68/64 scope link
       valid_lft forever preferred_lft forever

Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
2016-12-20 09:02:46.259 DEBUG neutron.agent.linux.utils [-] Unable to access /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/pid get_value_from_file /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:222
Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'dnsmasq', '--no-hosts', '--no-resolv', '--strict-order', '--bind-interfaces', '--interface=tap5c7f794d-08', '--except-interface=lo', '--pid-file=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/pid', '--dhcp-hostsfile=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/host', '--addn-hosts=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/addn_hosts', '--dhcp-optsfile=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/opts', '--dhcp-leasefile=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/leases', '--dhcp-range=set:tag0,20.0.0.0,static,86400s', '--dhcp-lease-max=256', '--conf-file=/etc/neutron/dnsmasq.conf', '--domain=openstacklocal']
Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'dnsmasq', '--no-hosts', '--no-resolv', '--strict-order', '--bind-interfaces', '--interface=tap995da463-09', '--except-interface=lo', '--pid-file=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/pid', '--dhcp-hostsfile=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/host', '--addn-hosts=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/addn_hosts', '--dhcp-optsfile=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/opts', '--dhcp-leasefile=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/leases', '--dhcp-range=set:tag0,20.0.1.0,static,86400s', '--dhcp-lease-max=256', '--conf-file=/etc/neutron/dnsmasq.conf', '--domain=openstacklocal']
Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
2016-12-20 09:02:46.483 INFO neutron.agent.dhcp.agent [req-555b9ae None None] Synchronizing state complete
2016-12-20 09:02:46.483 DEBUG oslo_concurrency.lockutils [req-555b9ae None None] Lock "dhcp-agent" released by "sync_state" :: held 2.031s inner /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:456


*****************
Explanations:
09:02:42.200: Dhcpagent config is loaded

09:02:42.214: FIRST networks initialization BEGIN
09:02:43.441: killing dnsmasq processes
09:02:43.459 - 09:02:44.154: configuration TAP interface
09:02:44.154 - 09:02:44.175: building dnsmasq files
09:02:44.313 - 09:02:44.441: launching dnsmasq processes
09:02:44.441: FIRST networks initialization END

09:02:44.453: SECOND networks initialization BEGIN
09:02:44.704: killing DNSMASQ processes
09:02:44.836 - 09:02:45.862: configuration TAP interface
09:02:45.862 - 09:02:46.107: building dnsmasq files
09:02:46.259 - 09:02:46.483: launching dnsmasq processes
09:02:46.483: SECOND networks initialization END

** Affects: neutron
     Importance: Undecided
     Assignee: Bertrand Lallau (bertrand-lallau)
         Status: New

** Changed in: neutron
     Assignee: (unassigned) => Bertrand Lallau (bertrand-lallau)

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

Title:
  Dhcpagent not efficient during initialization process

Status in neutron:
  New

Bug description:
  During DhcpAgent startup procedure all networks initialization will be done twice:
   * Killing old dnsmasq processes
   * set and configure all TAP interfaces
   * building all Dnsmasq config files (lease and host files)
   * launching dnsmasq processes
  This is really inefficient and can be strange in case of namespaces monitoring.

  
  The following Dhcpagent traces show the procedure describe just above (logs have been cleanup to show only relevant informations)

  
  2016-12-20 09:02:42.200 DEBUG neutron.openstack.common.service [req-b0a2772 None None] ******************************************************************************** log_opt_values /usr/lib/python2.7/dist-packages/oslo_config/cfg.py:2197
  2016-12-20 09:02:42.214 INFO neutron.agent.dhcp.agent [-] Synchronizing state
  2016-12-20 09:02:43.262 DEBUG neutron.agent.dhcp.agent [-] Calling driver for network: 5be9fe58-0790-4342-9182-172438e8e0bc action: enable call_driver /usr/lib/python2.7/dist-packages/neutron/agent/dhcp/agent.py:106
  2016-12-20 09:02:43.314 DEBUG neutron.agent.dhcp.agent [-] Calling driver for network: f2a73fc1-6a93-4822-aa45-3333b789d50d action: enable call_driver /usr/lib/python2.7/dist-packages/neutron/agent/dhcp/agent.py:106
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'kill', '-9', '24540']
  2016-12-20 09:02:43.441 DEBUG neutron.agent.linux.utils [-] Unable to access /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/pid get_value_from_file /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:222
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'kill', '-9', '24542']
  2016-12-20 09:02:43.459 DEBUG neutron.agent.linux.utils [-] Unable to access /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/pid get_value_from_file /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:222
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', 'link', 'set', 'tap5c7f794d-08', 'up']
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', 'link', 'set', 'tap995da463-09', 'up']
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', 'addr', 'show', 'tap5c7f794d-08', 'permanent', 'scope', 'global']
  Stdout: 32: tap5c7f794d-08: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default
      link/ether fa:16:3e:6b:cb:29 brd ff:ff:ff:ff:ff:ff
      inet 20.0.0.36/24 brd 20.0.0.255 scope global tap5c7f794d-08
         valid_lft forever preferred_lft forever
      inet 169.254.169.254/16 brd 169.254.255.255 scope global tap5c7f794d-08
         valid_lft forever preferred_lft forever

  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', 'addr', 'show', 'tap995da463-09', 'permanent', 'scope', 'global']
  Stdout: 35: tap995da463-09: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default
      link/ether fa:16:3e:49:6e:68 brd ff:ff:ff:ff:ff:ff
      inet 20.0.1.36/24 brd 20.0.1.255 scope global tap995da463-09
         valid_lft forever preferred_lft forever
      inet 169.254.169.254/16 brd 169.254.255.255 scope global tap995da463-09
         valid_lft forever preferred_lft forever

  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', '-4', 'route', 'list', 'dev', 'tap995da463-09', 'scope', 'link']
  Stdout: 20.0.1.0/24  proto kernel  src 20.0.1.36
  169.254.0.0/16  proto kernel  src 169.254.169.254

  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', '-4', 'route', 'list', 'dev', 'tap5c7f794d-08', 'scope', 'link']
  Stdout: 20.0.0.0/24  proto kernel  src 20.0.0.36
  169.254.0.0/16  proto kernel  src 169.254.169.254

  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', '-6', 'route', 'list', 'dev', 'tap995da463-09', 'scope', 'link']
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', '-6', 'route', 'list', 'dev', 'tap5c7f794d-08', 'scope', 'link']
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', 'route', 'list', 'dev', 'tap995da463-09']
  Stdout: 20.0.1.0/24  proto kernel  scope link  src 20.0.1.36
  169.254.0.0/16  proto kernel  scope link  src 169.254.169.254
  2016-12-20 09:02:44.154 DEBUG neutron.agent.linux.dhcp [-] Building initial lease file: /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/leases _output_init_lease_file /home/T0125936/work/curr/neutron/neutron/agent/linux/dhcp.py:480
  2016-12-20 09:02:44.155 DEBUG neutron.agent.linux.dhcp [-] Done building initial lease file /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/leases with contents:
  1482310964 fa:16:3e:49:6e:68 20.0.1.36 * *
  1482310964 fa:16:3e:81:6c:f3 20.0.1.35 * *
   _output_init_lease_file /home/T0125936/work/curr/neutron/neutron/agent/linux/dhcp.py:507
  2016-12-20 09:02:44.156 DEBUG neutron.agent.linux.dhcp [-] Building host file: /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/host _output_hosts_file neutron/agent/linux/dhcp.py:538
  2016-12-20 09:02:44.156 DEBUG neutron.agent.linux.dhcp [-] Done building host file /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/host with contents:
  fa:16:3e:49:6e:68,host-20-0-1-36.openstacklocal,20.0.1.36
  fa:16:3e:81:6c:f3,host-20-0-1-35.openstacklocal,20.0.1.35
   _output_hosts_file neutron/agent/linux/dhcp.py:567
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', 'route', 'list', 'dev', 'tap5c7f794d-08']
  Stdout: 20.0.0.0/24  proto kernel  scope link  src 20.0.0.36
  169.254.0.0/16  proto kernel  scope link  src 169.254.169.254

  Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
  2016-12-20 09:02:44.173 DEBUG neutron.agent.linux.dhcp [-] Building initial lease file: /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/leases _output_init_lease_file neutron/agent/linux/dhcp.py:480
  2016-12-20 09:02:44.173 DEBUG neutron.agent.linux.dhcp [-] Done building initial lease file /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/leases with contents:
  1482310964 fa:16:3e:6b:cb:29 20.0.0.36 * *
  1482310964 fa:16:3e:74:32:29 20.0.0.35 * *
   _output_init_lease_file neutron/agent/linux/dhcp.py:507
  2016-12-20 09:02:44.174 DEBUG neutron.agent.linux.dhcp [-] Building host file: /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/host _output_hosts_file neutron/agent/linux/dhcp.py:538
  2016-12-20 09:02:44.175 DEBUG neutron.agent.linux.dhcp [-] Done building host file /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/host with contents:
  fa:16:3e:6b:cb:29,host-20-0-0-36.openstacklocal,20.0.0.36
  fa:16:3e:74:32:29,host-20-0-0-35.openstacklocal,20.0.0.35
   _output_hosts_file neutron/agent/linux/dhcp.py:567
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', 'addr', 'show', 'tap995da463-09']
  Stdout: 35: tap995da463-09: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default
      link/ether fa:16:3e:49:6e:68 brd ff:ff:ff:ff:ff:ff
      inet 20.0.1.36/24 brd 20.0.1.255 scope global tap995da463-09
         valid_lft forever preferred_lft forever
      inet 169.254.169.254/16 brd 169.254.255.255 scope global tap995da463-09
         valid_lft forever preferred_lft forever
      inet6 fe80::f816:3eff:fe49:6e68/64 scope link
         valid_lft forever preferred_lft forever

  Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
  2016-12-20 09:02:44.293 DEBUG neutron.agent.linux.utils [-] Unable to access /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/pid get_value_from_file /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:222
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', 'addr', 'show', 'tap5c7f794d-08']
  Stdout: 32: tap5c7f794d-08: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default
      link/ether fa:16:3e:6b:cb:29 brd ff:ff:ff:ff:ff:ff
      inet 20.0.0.36/24 brd 20.0.0.255 scope global tap5c7f794d-08
         valid_lft forever preferred_lft forever
      inet 169.254.169.254/16 brd 169.254.255.255 scope global tap5c7f794d-08
         valid_lft forever preferred_lft forever
      inet6 fe80::f816:3eff:fe6b:cb29/64 scope link
         valid_lft forever preferred_lft forever

  Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
  2016-12-20 09:02:44.313 DEBUG neutron.agent.linux.utils [-] Unable to access /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/pid get_value_from_file /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:222
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'dnsmasq', '--no-hosts', '--no-resolv', '--strict-order', '--bind-interfaces', '--interface=tap995da463-09', '--except-interface=lo', '--pid-file=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/pid', '--dhcp-hostsfile=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/host', '--addn-hosts=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/addn_hosts', '--dhcp-optsfile=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/opts', '--dhcp-leasefile=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/leases', '--dhcp-range=set:tag0,20.0.1.0,static,86400s', '--dhcp-lease-max=256', '--conf-file=/etc/neutron/dnsmasq.conf', '--domain=openstacklocal']
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'dnsmasq', '--no-hosts', '--no-resolv', '--strict-order', '--bind-interfaces', '--interface=tap5c7f794d-08', '--except-interface=lo', '--pid-file=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/pid', '--dhcp-hostsfile=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/host', '--addn-hosts=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/addn_hosts', '--dhcp-optsfile=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/opts', '--dhcp-leasefile=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/leases', '--dhcp-range=set:tag0,20.0.0.0,static,86400s', '--dhcp-lease-max=256', '--conf-file=/etc/neutron/dnsmasq.conf', '--domain=openstacklocal']
  2016-12-20 09:02:44.441 INFO neutron.agent.dhcp.agent [-] Synchronizing state complete

  2016-12-20 09:02:44.453 DEBUG oslo_concurrency.lockutils [req-555b9ae None None] Lock "dhcp-agent" acquired by "sync_state" :: waited 2.081s inner /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:444
  2016-12-20 09:02:44.453 INFO neutron.agent.dhcp.agent [req-555b9ae None None] Synchronizing state
  2016-12-20 09:02:44.479 INFO neutron.agent.dhcp.agent [-] DHCP agent started
  2016-12-20 09:02:44.696 DEBUG neutron.agent.dhcp.agent [-] Calling driver for network: 5be9fe58-0790-4342-9182-172438e8e0bc action: enable call_driver /usr/lib/python2.7/dist-packages/neutron/agent/dhcp/agent.py:106
  2016-12-20 09:02:44.704 DEBUG neutron.agent.dhcp.agent [-] Calling driver for network: f2a73fc1-6a93-4822-aa45-3333b789d50d action: enable call_driver /usr/lib/python2.7/dist-packages/neutron/agent/dhcp/agent.py:106
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'kill', '-9', '24936']
  2016-12-20 09:02:44.820 DEBUG neutron.agent.linux.utils [-] Unable to access /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/pid get_value_from_file /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:222
  2016-12-20 09:02:44.836 DEBUG neutron.agent.linux.utils [-] Unable to access /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/pid get_value_from_file /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:222
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', 'link', 'set', 'tap5c7f794d-08', 'up']
  2016-12-20 09:02:45.126 DEBUG neutron.agent.linux.dhcp [-] Reusing existing device: tap5c7f794d-08. setup neutron/agent/linux/dhcp.py:1009
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', 'link', 'set', 'tap995da463-09', 'up']
  2016-12-20 09:02:45.192 DEBUG neutron.agent.linux.dhcp [-] Reusing existing device: tap995da463-09. setup neutron/agent/linux/dhcp.py:1009
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', 'addr', 'show', 'tap5c7f794d-08', 'permanent', 'scope', 'global']
  Stdout: 32: tap5c7f794d-08: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default
      link/ether fa:16:3e:6b:cb:29 brd ff:ff:ff:ff:ff:ff
      inet 20.0.0.36/24 brd 20.0.0.255 scope global tap5c7f794d-08
         valid_lft forever preferred_lft forever
      inet 169.254.169.254/16 brd 169.254.255.255 scope global tap5c7f794d-08
         valid_lft forever preferred_lft forever

  Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
  2016-12-20 09:02:45.386 DEBUG neutron.agent.linux.utils [-]
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', 'addr', 'show', 'tap995da463-09', 'permanent', 'scope', 'global']
  Stdout: 35: tap995da463-09: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default
      link/ether fa:16:3e:49:6e:68 brd ff:ff:ff:ff:ff:ff
      inet 20.0.1.36/24 brd 20.0.1.255 scope global tap995da463-09
         valid_lft forever preferred_lft forever
      inet 169.254.169.254/16 brd 169.254.255.255 scope global tap995da463-09
         valid_lft forever preferred_lft forever

  Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', '-4', 'route', 'list', 'dev', 'tap5c7f794d-08', 'scope', 'link']
  Stdout: 20.0.0.0/24  proto kernel  src 20.0.0.36
  169.254.0.0/16  proto kernel  src 169.254.169.254

  Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', '-4', 'route', 'list', 'dev', 'tap995da463-09', 'scope', 'link']
  Stdout: 20.0.1.0/24  proto kernel  src 20.0.1.36
  169.254.0.0/16  proto kernel  src 169.254.169.254

  Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', '-6', 'route', 'list', 'dev', 'tap5c7f794d-08', 'scope', 'link']
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', '-6', 'route', 'list', 'dev', 'tap995da463-09', 'scope', 'link']
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', 'route', 'list', 'dev', 'tap5c7f794d-08']
  Stdout: 20.0.0.0/24  proto kernel  scope link  src 20.0.0.36
  169.254.0.0/16  proto kernel  scope link  src 169.254.169.254

  Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
  2016-12-20 09:02:45.862 DEBUG neutron.agent.linux.dhcp [-] Building initial lease file: /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/leases _output_init_lease_file neutron/agent/linux/dhcp.py:480
  2016-12-20 09:02:45.863 DEBUG neutron.agent.linux.dhcp [-] Done building initial lease file /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/leases with contents:
  1482310965 fa:16:3e:6b:cb:29 20.0.0.36 * *
  1482310965 fa:16:3e:74:32:29 20.0.0.35 * *
   _output_init_lease_file neutron/agent/linux/dhcp.py:507
  2016-12-20 09:02:45.865 DEBUG neutron.agent.linux.dhcp [-] Building host file: /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/host _output_hosts_file neutron/agent/linux/dhcp.py:538
  2016-12-20 09:02:45.874 DEBUG neutron.agent.linux.dhcp [-] Done building host file /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/host with contents:
  fa:16:3e:6b:cb:29,host-20-0-0-36.openstacklocal,20.0.0.36
  fa:16:3e:74:32:29,host-20-0-0-35.openstacklocal,20.0.0.35
   _output_hosts_file neutron/agent/linux/dhcp.py:567
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', 'route', 'list', 'dev', 'tap995da463-09']
  Exit code: 0
  Stdin:
  Stdout: 20.0.1.0/24  proto kernel  scope link  src 20.0.1.36
  169.254.0.0/16  proto kernel  scope link  src 169.254.169.254

  Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
  2016-12-20 09:02:45.971 DEBUG neutron.agent.linux.dhcp [-] Building initial lease file: /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/leases _output_init_lease_file neutron/agent/linux/dhcp.py:480
  2016-12-20 09:02:45.977 DEBUG neutron.agent.linux.dhcp [-] Done building initial lease file /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/leases with contents:
  1482310965 fa:16:3e:49:6e:68 20.0.1.36 * *
  1482310965 fa:16:3e:81:6c:f3 20.0.1.35 * *
   _output_init_lease_file neutron/agent/linux/dhcp.py:507
  2016-12-20 09:02:45.978 DEBUG neutron.agent.linux.dhcp [-] Building host file: /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/host _output_hosts_file neutron/agent/linux/dhcp.py:538
  2016-12-20 09:02:45.986 DEBUG neutron.agent.linux.dhcp [-] Done building host file /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/host with contents:
  fa:16:3e:49:6e:68,host-20-0-1-36.openstacklocal,20.0.1.36
  fa:16:3e:81:6c:f3,host-20-0-1-35.openstacklocal,20.0.1.35
   _output_hosts_file neutron/agent/linux/dhcp.py:567
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'ip', 'addr', 'show', 'tap5c7f794d-08']
  Stdout: 32: tap5c7f794d-08: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default
      link/ether fa:16:3e:6b:cb:29 brd ff:ff:ff:ff:ff:ff
      inet 20.0.0.36/24 brd 20.0.0.255 scope global tap5c7f794d-08
         valid_lft forever preferred_lft forever
      inet 169.254.169.254/16 brd 169.254.255.255 scope global tap5c7f794d-08
         valid_lft forever preferred_lft forever
      inet6 fe80::f816:3eff:fe6b:cb29/64 scope link
         valid_lft forever preferred_lft forever

  Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
  2016-12-20 09:02:46.107 DEBUG neutron.agent.linux.utils [-] Unable to access /var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/pid get_value_from_file /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:222
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'ip', 'addr', 'show', 'tap995da463-09']
  Stdout: 35: tap995da463-09: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UNKNOWN group default
      link/ether fa:16:3e:49:6e:68 brd ff:ff:ff:ff:ff:ff
      inet 20.0.1.36/24 brd 20.0.1.255 scope global tap995da463-09
         valid_lft forever preferred_lft forever
      inet 169.254.169.254/16 brd 169.254.255.255 scope global tap995da463-09
         valid_lft forever preferred_lft forever
      inet6 fe80::f816:3eff:fe49:6e68/64 scope link
         valid_lft forever preferred_lft forever

  Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
  2016-12-20 09:02:46.259 DEBUG neutron.agent.linux.utils [-] Unable to access /var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/pid get_value_from_file /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:222
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-5be9fe58-0790-4342-9182-172438e8e0bc', 'dnsmasq', '--no-hosts', '--no-resolv', '--strict-order', '--bind-interfaces', '--interface=tap5c7f794d-08', '--except-interface=lo', '--pid-file=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/pid', '--dhcp-hostsfile=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/host', '--addn-hosts=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/addn_hosts', '--dhcp-optsfile=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/opts', '--dhcp-leasefile=/var/lib/neutron/dhcp/5be9fe58-0790-4342-9182-172438e8e0bc/leases', '--dhcp-range=set:tag0,20.0.0.0,static,86400s', '--dhcp-lease-max=256', '--conf-file=/etc/neutron/dnsmasq.conf', '--domain=openstacklocal']
  Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
  Command: ['sudo', '/usr/bin/neutron-rootwrap', '/etc/neutron/rootwrap.conf', 'ip', 'netns', 'exec', 'qdhcp-f2a73fc1-6a93-4822-aa45-3333b789d50d', 'dnsmasq', '--no-hosts', '--no-resolv', '--strict-order', '--bind-interfaces', '--interface=tap995da463-09', '--except-interface=lo', '--pid-file=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/pid', '--dhcp-hostsfile=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/host', '--addn-hosts=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/addn_hosts', '--dhcp-optsfile=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/opts', '--dhcp-leasefile=/var/lib/neutron/dhcp/f2a73fc1-6a93-4822-aa45-3333b789d50d/leases', '--dhcp-range=set:tag0,20.0.1.0,static,86400s', '--dhcp-lease-max=256', '--conf-file=/etc/neutron/dnsmasq.conf', '--domain=openstacklocal']
  Stderr:  execute /usr/lib/python2.7/dist-packages/neutron/agent/linux/utils.py:134
  2016-12-20 09:02:46.483 INFO neutron.agent.dhcp.agent [req-555b9ae None None] Synchronizing state complete
  2016-12-20 09:02:46.483 DEBUG oslo_concurrency.lockutils [req-555b9ae None None] Lock "dhcp-agent" released by "sync_state" :: held 2.031s inner /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:456

  
  *****************
  Explanations:
  09:02:42.200: Dhcpagent config is loaded

  09:02:42.214: FIRST networks initialization BEGIN
  09:02:43.441: killing dnsmasq processes
  09:02:43.459 - 09:02:44.154: configuration TAP interface
  09:02:44.154 - 09:02:44.175: building dnsmasq files
  09:02:44.313 - 09:02:44.441: launching dnsmasq processes
  09:02:44.441: FIRST networks initialization END

  09:02:44.453: SECOND networks initialization BEGIN
  09:02:44.704: killing DNSMASQ processes
  09:02:44.836 - 09:02:45.862: configuration TAP interface
  09:02:45.862 - 09:02:46.107: building dnsmasq files
  09:02:46.259 - 09:02:46.483: launching dnsmasq processes
  09:02:46.483: SECOND networks initialization END

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

[Bug 1651368] Re: Dhcpagent not efficient during initialization process
From: OpenStack Infra, 2017-01-19