Spawning of DHCP processes fail: invalid netcat options

[Carlos Goncalves]

Devstack master, ML2/OVS, CentOS 7, Python 3.6.

No DHCP servers running. Instances fail to get a DHCP offer.

$ ps aux | egrep "dhcp|dnsmasq"
vagrant 591 4.7 0.7 459196 114056 ? Ss 07:26 0:33 /usr/bin/python3.6 /usr/local/bin/neutron-dhcp-agent --config-file /etc/neutron/neutron.conf --config-file /etc/neutron/dhcp_agent.ini
root 1057 0.0 0.0 102896 5472 ? S 06:14 0:00 /sbin/dhclient -d -q -sf /usr/libexec/nm-dhcp-helper -pf /var/run/dhclient-eth0.pid -lf /var/lib/NetworkManager/dhclient-5fb06bd0-0bb0-7ffb-45f1-d6edd65f3e03-eth0.lease -cf /var/lib/NetworkManager/dhclient-eth0.conf eth0
root 1219 14.9 0.4 684168 77988 ? Sl 07:26 1:43 /usr/bin/python3.6 /usr/local/bin/privsep-helper --config-file /etc/neutron/neutron.conf --config-file /etc/neutron/dhcp_agent.ini --privsep_context neutron.privileged.default --privsep_sock_path /tmp/tmpxg0wq6j2/privsep.sock
root 14783 0.0 0.0 102896 2632 ? Ss 07:29 0:00 dhclient -v o-hm0 -cf /etc/dhcp/octavia/dhclient.conf
vagrant 18136 0.0 0.0 112716 988 pts/2 S+ 07:37 0:00 grep -E --color=auto dhcp|dnsmasq

Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: DEBUG neutron.agent.linux.dhcp [None req-4193fed2-5a2d-4c24-b3b1-72673dc2e1fe None None] Building initial lease file: /opt/stack/data/neutron/dhcp/06d0ae0b-d730-4871-bef3-fa52e8638214/leases {{(pid=591) _output_init_lease_file /opt/stack/neutron/neutron/agent/linux/dhcp.py:681}}
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: DEBUG neutron.agent.linux.dhcp [None req-4193fed2-5a2d-4c24-b3b1-72673dc2e1fe None None] Done building initial lease file /opt/stack/data/neutron/dhcp/06d0ae0b-d730-4871-bef3-fa52e8638214/leases with contents:
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: 1581752053 fa:16:3e:31:b7:ea 192.168.233.2 * *
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: {{(pid=591) _output_init_lease_file /opt/stack/neutron/neutron/agent/linux/dhcp.py:708}}
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: DEBUG neutron.agent.linux.dhcp [None req-4193fed2-5a2d-4c24-b3b1-72673dc2e1fe None None] Building host file: /opt/stack/data/neutron/dhcp/06d0ae0b-d730-4871-bef3-fa52e8638214/host {{(pid=591) _output_hosts_file /opt/stack/neutron/neutron/agent/linux/dhcp.py:739}}
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: DEBUG neutron.agent.linux.dhcp [None req-4193fed2-5a2d-4c24-b3b1-72673dc2e1fe None None] Done building host file /opt/stack/data/neutron/dhcp/06d0ae0b-d730-4871-bef3-fa52e8638214/host {{(pid=591) _output_hosts_file /opt/stack/neutron/neutron/agent/linux/dhcp.py:780}}
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: DEBUG neutron.agent.linux.utils [None req-4193fed2-5a2d-4c24-b3b1-72673dc2e1fe None None] Unable to access /opt/stack/data/neutron/dhcp/06d0ae0b-d730-4871-bef3-fa52e8638214/pid; Error: [Errno 2] No such file or directory: '/opt/stack/data/neutron/dhcp/06d0ae0b-d730-4871-bef3-fa52e8638214/pid' {{(pid=591) get_value_from_file /opt/stack/neutron/neutron/agent/linux/utils.py:262}}
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: DEBUG neutron.agent.linux.utils [None req-4193fed2-5a2d-4c24-b3b1-72673dc2e1fe None None] Running command (rootwrap daemon): ['ip', 'netns', 'exec', 'qdhcp-06d0ae0b-d730-4871-bef3-fa52e8638214', 'dnsmasq', '--no-hosts', '', '--pid-file=/opt/stack/data/neutron/dhcp/06d0ae0b-d730-4871-bef3-fa52e8638214/pid', '--dhcp-hostsfile=/opt/stack/data/neutron/dhcp/06d0ae0b-d730-4871-bef3-fa52e8638214/host', '--addn-hosts=/opt/stack/data/neutron/dhcp/06d0ae0b-d730-4871-bef3-fa52e8638214/addn_hosts', '--dhcp-optsfile=/opt/stack/data/neutron/dhcp/06d0ae0b-d730-4871-bef3-fa52e8638214/opts', '--dhcp-leasefile=/opt/stack/data/neutron/dhcp/06d0ae0b-d730-4871-bef3-fa52e8638214/leases', '--dhcp-match=set:ipxe,175', '--dhcp-userclass=set:ipxe6,iPXE', '--local-service', '--bind-dynamic', '--dhcp-range=set:subnet-879783df-943d-486d-8447-8730b9f3051a,192.168.233.0,static,255.255.255.0,86400s', '--dhcp-option-force=option:mtu,1450', '--dhcp-lease-max=256', '--conf-file=', '--domain=openstacklocal'] {{(pid=591) execute_rootwrap_daemon /opt/stack/neutron/neutron/agent/linux/utils.py:103}}
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: ERROR neutron.agent.linux.utils [None req-4193fed2-5a2d-4c24-b3b1-72673dc2e1fe None None] Exit code: 2; Stdin: ; Stdout: ; Stderr: /bin/ncat: unrecognized option '--no-hosts'
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: Ncat: Try `--help' or man(1) ncat for more information, usage options and help. QUITTING.
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]:
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: DEBUG neutron.agent.linux.dhcp [None req-4193fed2-5a2d-4c24-b3b1-72673dc2e1fe None None] Spawning DHCP process for network 06d0ae0b-d730-4871-bef3-fa52e8638214 failed; Error: Exit code: 2; Stdin: ; Stdout: ; Stderr: /bin/ncat: unrecognized option '--no-hosts'
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: Ncat: Try `--help' or man(1) ncat for more information, usage options and help. QUITTING.
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: {{(pid=591) _enable /opt/stack/neutron/neutron/agent/linux/dhcp.py:274}}
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: DEBUG neutron.agent.linux.utils [None req-24ab0d08-e2ab-4216-b3ce-cac571f5779e None None] Unable to access /opt/stack/data/neutron/dhcp/eb8e5a83-ca01-4cb0-82ec-d1d4ecc14e9f/pid; Error: [Errno 2] No such file or directory: '/opt/stack/data/neutron/dhcp/eb8e5a83-ca01-4cb0-82ec-d1d4ecc14e9f/pid' {{(pid=591) get_value_from_file /opt/stack/neutron/neutron/agent/linux/utils.py:262}}
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: DEBUG oslo.privsep.daemon [-] privsep: reply[140123534145688]: (4, ['qdhcp-06d0ae0b-d730-4871-bef3-fa52e8638214', 'qdhcp-70e0b5b4-92c6-4dfc-8d5d-81e908170bdd', 'qdhcp-eb8e5a83-ca01-4cb0-82ec-d1d4ecc14e9f']) {{(pid=1219) _call_back /usr/local/lib/python3.6/site-packages/oslo_privsep/daemon.py:475}}
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: DEBUG neutron.agent.linux.utils [None req-24ab0d08-e2ab-4216-b3ce-cac571f5779e None None] Running command (rootwrap daemon): ['ip', 'netns', 'exec', 'qdhcp-eb8e5a83-ca01-4cb0-82ec-d1d4ecc14e9f', 'sysctl', '-w', 'net.ipv4.ip_nonlocal_bind=1'] {{(pid=591) execute_rootwrap_daemon /opt/stack/neutron/neutron/agent/linux/utils.py:103}}
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: WARNING neutron.agent.linux.ip_lib [None req-24ab0d08-e2ab-4216-b3ce-cac571f5779e None None] Setting ['sysctl', '-w', 'net.ipv4.ip_nonlocal_bind=1'] in namespace qdhcp-eb8e5a83-ca01-4cb0-82ec-d1d4ecc14e9f failed: Exit code: 2; Stdin: ; Stdout: ; Stderr: Ncat: Invalid -w timeout (must be greater than 0). QUITTING.
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: .: neutron_lib.exceptions.ProcessExecutionError: Exit code: 2; Stdin: ; Stdout: ; Stderr: Ncat: Invalid -w timeout (must be greater than 0). QUITTING.
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: DEBUG neutron.agent.linux.ip_lib [None req-24ab0d08-e2ab-4216-b3ce-cac571f5779e None None] Namespace (qdhcp-eb8e5a83-ca01-4cb0-82ec-d1d4ecc14e9f) does not support setting net.ipv4.ip_nonlocal_bind, trying in root namespace {{(pid=591) set_ip_nonlocal_bind_for_namespace /opt/stack/neutron/neutron/agent/linux/ip_lib.py:1136}}
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: DEBUG neutron.agent.linux.utils [None req-24ab0d08-e2ab-4216-b3ce-cac571f5779e None None] Running command (rootwrap daemon): ['sysctl', '-w', 'net.ipv4.ip_nonlocal_bind=1'] {{(pid=591) execute_rootwrap_daemon /opt/stack/neutron/neutron/agent/linux/utils.py:103}}
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: DEBUG neutron.agent.linux.utils [None req-24ab0d08-e2ab-4216-b3ce-cac571f5779e None None] Running command (rootwrap daemon): ['ip', 'netns', 'exec', 'qdhcp-eb8e5a83-ca01-4cb0-82ec-d1d4ecc14e9f', 'sysctl', '-w', 'net.ipv6.conf.default.accept_ra=0'] {{(pid=591) execute_rootwrap_daemon /opt/stack/neutron/neutron/agent/linux/utils.py:103}}
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: ERROR neutron.agent.linux.utils [None req-24ab0d08-e2ab-4216-b3ce-cac571f5779e None None] Exit code: 2; Stdin: ; Stdout: ; Stderr: Ncat: Invalid -w timeout (must be greater than 0). QUITTING.
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]:
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: WARNING neutron.agent.linux.ip_lib [None req-24ab0d08-e2ab-4216-b3ce-cac571f5779e None None] Setting ['sysctl', '-w', 'net.ipv6.conf.default.accept_ra=0'] in namespace qdhcp-eb8e5a83-ca01-4cb0-82ec-d1d4ecc14e9f failed: Exit code: 2; Stdin: ; Stdout: ; Stderr: Ncat: Invalid -w timeout (must be greater than 0). QUITTING.
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: .: neutron_lib.exceptions.ProcessExecutionError: Exit code: 2; Stdin: ; Stdout: ; Stderr: Ncat: Invalid -w timeout (must be greater than 0). QUITTING.
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: DEBUG oslo.privsep.daemon [-] privsep: reply[140123534145688]: (4, True) {{(pid=1219) _call_back /usr/local/lib/python3.6/site-packages/oslo_privsep/daemon.py:475}}
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: DEBUG oslo.privsep.daemon [-] privsep: reply[140123534145688]: (4, {'mtu': 1450, 'qlen': 1000, 'state': 'UNKNOWN', 'qdisc': 'noqueue', 'brd': 'ff:ff:ff:ff:ff:ff', 'link/ether': 'fa:16:3e:a0:0b:a3', 'alias': None, 'allmulticast': False, 'link_kind': 'openvswitch'}) {{(pid=1219) _call_back /usr/local/lib/python3.6/site-packages/oslo_privsep/daemon.py:475}}
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: DEBUG oslo.privsep.daemon [-] privsep: reply[140123534145688]: (4, ({'header': {'length': 36, 'type': 2, 'flags': 0, 'sequence_number': 255, 'pid': 9337, 'error': None, 'stats': Stats(qsize=0, delta=0, delay=0)}, 'event': 'NLMSG_ERROR'},)) {{(pid=1219) _call_back /usr/local/lib/python3.6/site-packages/oslo_privsep/daemon.py:475}}
Feb 14 07:34:13 localhost.localdomain neutron-dhcp-agent[591]: DEBUG neutron.agent.linux.dhcp [None req-24ab0d08-e2ab-4216-b3ce-cac571f5779e None None] Reusing existing device: tap5337fbe0-46. {{(pid=591) setup /opt/stack/neutron/neutron/agent/linux/dhcp.py:1586}}

[Slawek Kaplonski (slaweq)]

That error looks strange as we don't use netcat in dhcp agent at all. We are using ncat only in tests.
Can You give us exact version of dnsmasq and netcat installed on Your system?

[Rodolfo Alonso (rodolfo-alonso-hernandez)]

The error is in the ncat timeout parameter:

Stderr: Ncat: Invalid -w timeout (must be greater than 0). QUITTING.

We need to check that the timeout is always > 0.

[Carlos Goncalves (cgoncalves)]

[vagrant@localhost ~]$ rpm -q nmap-ncat
nmap-ncat-6.40-19.el7.x86_64
[vagrant@localhost ~]$ rpm -q dnsmasq
dnsmasq-2.76-10.el7_7.1.x86_64

[vagrant@localhost ~]$ ncat --version
Ncat: Version 7.50 ( https://nmap.org/ncat )
[vagrant@localhost ~]$ dnsmasq --version
Dnsmasq version 2.76 Copyright (c) 2000-2016 Simon Kelley
Compile time options: IPv6 GNU-getopt DBus no-i18n IDN DHCP DHCPv6 no-Lua TFTP no-conntrack ipset auth no-DNSSEC loop-detect inotify

This software comes with ABSOLUTELY NO WARRANTY.
Dnsmasq is free software, and you are welcome to redistribute it
under the terms of the GNU General Public License, version 2 or 3

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/707786
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=22ce84ab4d5b12348a58fd82828c4eacb04fd578
Submitter: Zuul
Branch: master

commit 22ce84ab4d5b12348a58fd82828c4eacb04fd578
Author: Rodolfo Alonso Hernandez <email address hidden>
Date: Fri Feb 14 08:57:07 2020 +0000

    Revert "Add "ncat" rootwrap filter for debug"

    This reverts commit 0ef4233d891f8fa42a073901051bf0310f61eebb.

    This patch is introducing a redundant filter already present in
    "testing.filters". The problem described in the related bug should
    be solved in https://review.opendev.org/#/c/707697/.

    Related-Bug: #1862927
    Related-Bug: #1863213

    Change-Id: I4de37364a6fb0184230a9742daced40e4edbfb30