https://redmine.pfsense.org/https://redmine.pfsense.org/favicon.ico?16780521162014-01-22T10:46:12ZpfSense bugtrackerpfSense - Bug #3404: DHCP Server Fails to Start on Interfaces that are Slow to Come Online During Boothttps://redmine.pfsense.org/issues/3404?journal_id=130272014-01-22T10:46:12ZErmal Luçieri@pfsense.org
<ul></ul><p>The proper solution for this is to bounce the dhcpd when the openvpn link comes up.<br />Check rc.newwanip[v6] script on this and there is the proper solution to be added.</p>
<p>From what i see dhcpd is not bumped from this script with the frame that dhcpd cannot run on dynamic interfaces.<br />Though some more checks can be added there to aid the need.</p> pfSense - Bug #3404: DHCP Server Fails to Start on Interfaces that are Slow to Come Online During Boothttps://redmine.pfsense.org/issues/3404?journal_id=130302014-01-22T12:43:44ZMicah Mitchell
<ul><li><strong>File</strong> <a href="/attachments/917">services.inc.patch</a> <a class="icon-only icon-download" title="Download" href="/attachments/download/917/services.inc.patch">services.inc.patch</a> added</li></ul><p>I have attached a patch file for /etc/inc/services.inc</p>
<p>This will have the services_dhcpd_configure() function check the config for enabled interfaces with enabled dhcp servers and then give the interface up to 10 seconds to come up before continuing on. This is based on the same logic that used with checking if ppp(oe) interfaces have come online.</p>
<p>This code only waits if both the interface and dhcp server are enabled and the interface is not up.</p>
<p>I have tested this on the gateway that Jason was referencing above and it did fix our issue. It only added a 2 second delay during boot to allow the OpenVPN interface to come up. If no OpenVPN interfaces are enabled, there is no delay during boot.</p> pfSense - Bug #3404: DHCP Server Fails to Start on Interfaces that are Slow to Come Online During Boothttps://redmine.pfsense.org/issues/3404?journal_id=130332014-01-22T14:30:49ZErmal Luçieri@pfsense.org
<ul></ul><p>Please read my comment on the proper solution.<br />This is a workaround/hack for your local installation.</p> pfSense - Bug #3404: DHCP Server Fails to Start on Interfaces that are Slow to Come Online During Boothttps://redmine.pfsense.org/issues/3404?journal_id=130542014-01-24T08:07:24ZJason Crowleyjcrowley@in-kc.com
<ul><li><strong>File</strong> <a href="/attachments/919">openvpn.inc.patch</a> <a class="icon-only icon-download" title="Download" href="/attachments/download/919/openvpn.inc.patch">openvpn.inc.patch</a> added</li></ul><p>Thanks for the help Ermal. When I try to bounce dhcpd in the rc.newwanip script, I run into a problem where it appears that multiple instances of rc.newwanip are running simultaneously. Because of this, they try to write the dhcpd.conf file and start dhcpd on top of each other. I get output like this.</p>
<blockquote>
<p>rc.newwanip: The command '/usr/local/sbin/dhcpd -user dhcpd -group _dhcp -chroot /var/dhcpd -cf /etc/dhcpd.conf -pf /var/run/dhcpd.pid em0 em2' returned exit code '1', the output was 'Internet Systems Consortium DHCP Server 4.2.5-P1 Copyright 2004-2013 Internet Systems Consortium. All rights reserved. For info, please visit <a class="external" href="https://www.isc.org/software/dhcp/">https://www.isc.org/software/dhcp/</a> Wrote 4 leases to leases file. Listening on BPF/em2/1e:07:96:ec:8e:4e/172.28.68.224/27 Sending on BPF/em2/1e:07:96:ec:8e:4e/172.28.68.224/27 Listening on BPF/em0/ca:32:32:49:19:1d/172.28.68.0/25 Sending on BPF/em0/ca:32:32:49:19:1d/172.28.68.0/25 Can't bind to dhcp address: Address already in use Please make sure there is no other dhcp server running and that there's no entry for dhcp or bootp in /etc/inetd.conf.</p>
</blockquote>
<p>Also, I can see that rc.newwanip is getting called prior to the OpenVPN interface coming completely online.</p>
<p>When I run this command string:</p>
<blockquote>
<p>kill `cat /var/run/openvpn_server1.pid` ; /usr/local/sbin/openvpn --config /var/etc/openvpn/server1.conf ; date ; ifconfig ovpns1 ; sleep 1 ; date ; ifconfig ovpns1 ; sleep 1 ; date ; ifconfig ovpns1 ; sleep 1 ; date ; ifconfig ovpns1 ; sleep 1 ; date ; ifconfig ovpns1 ; sleep 1 ; date ; ifconfig ovpns1 ; sleep 1 ; date ; ifconfig ovpns1 ; sleep 1 ; date ; ifconfig ovpns1</p>
</blockquote>
<p>I get this output:<br /><pre>OK
Fri Jan 24 07:39:03 CST 2014
ovpns1: flags=8842<BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
options=80000<LINKSTATE>
ether 00:bd:4f:07:00:01
Opened by PID 71188
Fri Jan 24 07:39:04 CST 2014
ovpns1: flags=8842<BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
options=80000<LINKSTATE>
ether 00:bd:4f:07:00:01
Opened by PID 71188
Fri Jan 24 07:39:05 CST 2014
ovpns1: flags=8842<BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
options=80000<LINKSTATE>
ether 00:bd:4f:07:00:01
Opened by PID 71188
Fri Jan 24 07:39:06 CST 2014
ovpns1: flags=8842<BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
options=80000<LINKSTATE>
ether 00:bd:4f:07:00:01
Opened by PID 71188
Fri Jan 24 07:39:07 CST 2014
ovpns1: flags=8842<BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
options=80000<LINKSTATE>
ether 00:bd:4f:07:00:01
Opened by PID 71188
Fri Jan 24 07:39:08 CST 2014
ovpns1: flags=8842<BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
options=80000<LINKSTATE>
ether 00:bd:4f:07:00:01
Opened by PID 71188
Fri Jan 24 07:39:09 CST 2014
ovpns1: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
options=80000<LINKSTATE>
ether 00:bd:4f:07:00:01
inet 172.28.68.193 netmask 0xffffffe0 broadcast 172.28.68.223
inet6 fe80::2bd:4fff:fe07:1%ovpns1 prefixlen 64 tentative scopeid 0x8
nd6 options=1<PERFORMNUD>
Opened by PID 71188
Fri Jan 24 07:39:10 CST 2014
ovpns1: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
options=80000<LINKSTATE>
ether 00:bd:4f:07:00:01
inet 172.28.68.193 netmask 0xffffffe0 broadcast 172.28.68.223
inet6 fe80::2bd:4fff:fe07:1%ovpns1 prefixlen 64 scopeid 0x8
nd6 options=1<PERFORMNUD>
Opened by PID 71188
</pre></p>
<p>And I find this in system.log:<br /><pre>Jan 24 07:39:03 nfkcgw01 kernel: ovpns1: link state changed to DOWN
Jan 24 07:39:03 nfkcgw01 kernel: ovpns1: link state changed to UP
Jan 24 07:39:03 nfkcgw01 check_reload_status: rc.newwanip starting ovpns1
Jan 24 07:39:03 nfkcgw01 check_reload_status: Reloading filter
Jan 24 07:39:06 nfkcgw01 php: rc.newwanip: rc.newwanip: Informational is starting ovpns1.
Jan 24 07:39:06 nfkcgw01 php: rc.newwanip: rc.newwanip: on (IP address: ) (interface: opt2) (real interface: ovpns1)
.
Jan 24 07:39:06 nfkcgw01 php: rc.newwanip: rc.newwanip: Failed to update opt2 IP, restarting...
Jan 24 07:39:06 nfkcgw01 check_reload_status: Configuring interface opt2
Jan 24 07:39:07 nfkcgw01 php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (opt2).
Jan 24 07:39:09 nfkcgw01 php: rc.interfaces_wan_configure: Deny router advertisements for interface opt2</pre></p>
<p><strong>Note that rc.newwanip is getting called six seconds before the OpenVPN interface actually has an IP.</strong></p>
<p>I've added the code below to the openvpn_restart() function to wait for the OpenVPN interface to come up before returning. I've also attached this code in a patch file.<br /><pre>
/* look for interface to come up before continuing */
$i = 1;
while(mwexec("/sbin/ifconfig $devname | grep '[<,]UP[,>]'", true)) {
if($g['debug'])
log_error("Sleeping 1 second waiting for openvpn interface to come up attempt: $i of 10.\n")
;
sleep(1);
$i++;
if ($i > 10) {
log_error("Timeout waiting for openvpn interface $devname to come up.\n");
break;
}
}
</pre></p>
<p>That alleviates our problem but causes any call of that function to take 6-7 seconds on our test pfSense instance (1 virtual CPU: AMD @ 2.8 GHz).</p>
<p>Would it be better to put the loop in rc.newwanip[v6]? Do you think a 10-second time out will be enough? Do you have ideas for a way to do this without a timeout loop?</p> pfSense - Bug #3404: DHCP Server Fails to Start on Interfaces that are Slow to Come Online During Boothttps://redmine.pfsense.org/issues/3404?journal_id=130822014-01-30T23:19:27ZJason Crowleyjcrowley@in-kc.com
<ul></ul><p>I performed more testing with different configurations and locations for the wait loop today. My plan was to find where rc.newwanip was executed in the process of launching the openvpn process, and make sure it didn't start until the link was actually up. It appears that rc.newwanip is being called when the following code is executed from /usr/local/sbin/ovpn-linkup.<br /><pre>/usr/local/sbin/pfSctl -c "interface newip $1"</pre><br />The ovpn-linkup script is called by the openvpn process when it first establishes the link. Inserting the wait loop in that script was useless since the ovpns1 interface doesn't actually come online until after that script has completed and the openvpn process daemonizes.</p>
<p>It appears to me that my patch for openvpn.inc is adequate to resolve this bug. Ermal and others, would you agree? Do you feel there is anything else I need to do prior to merging this into the code base for further testing? Thanks!</p> pfSense - Bug #3404: DHCP Server Fails to Start on Interfaces that are Slow to Come Online During Boothttps://redmine.pfsense.org/issues/3404?journal_id=131422014-02-11T17:09:01ZChris Buechlercbuechler@gmail.com
<ul><li><strong>Target version</strong> deleted (<del><i>2.1.1</i></del>)</li><li><strong>Affected Version</strong> changed from <i>2.1</i> to <i>All</i></li></ul>