tests: confirm that _output_hosts_file does not log too often

I3ad7864eeb2f959549ed356a1e34fa18804395cc didn't include any regression unit
tests to validate that the method won't ever log too often again,
reintroducing performance drop in later patches. It didn't play well
with stable backports of the fix, where context was lost when doing the
backport, that left the bug unfixed in stable/juno even though the patch
was merged there [1].

The patch adds an explicit note in the code that suggests not to add new
log messages inside the loop to avoid regression, and a unit test was
added to capture it.

Once the test is merged in master, it will be proposed for stable/juno
inclusion, with additional changes that would fix the regression again.

Conflicts:
	neutron/agent/linux/dhcp.py
	neutron/tests/unit/test_linux_dhcp.py

Local changes:
- remove LOG.debug messages that sneaked into the for loop with a
  backport.

Related-Bug: #1414218
Change-Id: I5d43021932d6a994638c348eda277dd8337cf041
(cherry picked from commit 3b74095a93)

neutron/agent/linux/dhcp.py

@@ -518,13 +518,13 @@ class Dnsmasq(DhcpLocalProcess):
         filename = self.get_conf_file_name('host')
 
         LOG.debug(_('Building host file: %s'), filename)
+        # NOTE(ihrachyshka): the loop should not log anything inside it, to
+        # avoid potential performance drop when lots of hosts are dumped
         for (port, alloc, hostname, name) in self._iter_hosts():
             if not alloc:
                 if getattr(port, 'extra_dhcp_opts', False):
                     buf.write('%s,%s%s\n' %
                               (port.mac_address, 'set:', port.id))
-                LOG.debug('Adding %(mac)s : set:%(tag)s',
-                          {"mac": port.mac_address, "tag": port.id})
                 continue
 
             # (dzyu) Check if it is legal ipv6 address, if so, need wrap
@@ -538,16 +538,9 @@ class Dnsmasq(DhcpLocalProcess):
                 buf.write('%s,%s,%s,%s%s\n' %
                           (port.mac_address, name, ip_address,
                            'set:', port.id))
-                LOG.debug('Adding %(mac)s : %(name)s : %(ip)s : '
-                          'set:%(tag)s',
-                          {"mac": port.mac_address, "name": name,
-                           "ip": ip_address, "tag": port.id})
             else:
                 buf.write('%s,%s,%s\n' %
                           (port.mac_address, name, ip_address))
-                LOG.debug('Adding %(mac)s : %(name)s : %(ip)s',
-                          {"mac": port.mac_address, "name": name,
-                           "ip": ip_address})
 
         utils.replace_file(filename, buf.getvalue())
         LOG.debug('Done building host file %s with contents:\n%s', filename,

neutron/tests/unit/test_linux_dhcp.py

@@ -1427,6 +1427,17 @@ tag:tag0,option:router""".lstrip()
                                 float(2.66))
             self.assertTrue(warning.called)
 
+    def test__output_hosts_file_log_only_twice(self):
+        dm = dhcp.Dnsmasq(self.conf, FakeDualStackNetworkSingleDHCP(),
+                          version=dhcp.Dnsmasq.MINIMUM_VERSION)
+        with mock.patch.object(dhcp.LOG, 'process') as process:
+            process.return_value = ('fake_message', {})
+            dm._output_hosts_file()
+        # The method logs twice, at the start of and the end. There should be
+        # no other logs, no matter how many hosts there are to dump in the
+        # file.
+        self.assertEqual(2, process.call_count)
+
     def test_only_populates_dhcp_enabled_subnets(self):
         exp_host_name = '/dhcp/eeeeeeee-eeee-eeee-eeee-eeeeeeeeeeee/host'
         exp_host_data = ('00:00:80:aa:bb:cc,host-192-168-0-2.openstacklocal,'