IP address lease 0.0.0.0 has been denied

[libove]

I just re-started my Windows Server 2008 (32-bit, original edition, fully patched) with OpenVPN version information:
OpenVPN 2.1.3 i686-pc-mingw32 [SSL] [LZO2] [PKCS11] built on Aug 20 2010

The System Event Log began filling up with thousands of this error:

The IP address lease 0.0.0.0 for the Network Card with network address 00FF09A5E76E has been denied by the DHCP server 10.8.0.2 (The DHCP Server sent a DHCPNACK message).

The error occurred exactly once per second, every second, until I manually stopped the OpenVPN service when I noticed the errors an hour later. (Lots of errors in the log!)

The error messages began at 18:32:09, which is about five minutes after the OpenVPN Service started automatically at 18:26:27 during the server's normal boot up process. Note, this server is a very low-end machine, rather slow; I do not know why there was that long delay between the OpenVPN Service start and the beginning of the endless series of these errors in the System Log. The errors stopped instantly after I stopped the OpenVPN service. (Literally, the last of these error messages was the last event log entry before the event log entry indicating the OpenVPN Service stopping).

Oddly, when I re-started the OpenVPN Service a few minutes later, the errors did NOT start up again.

Here's the contents of the OpenVPN.log file from service start to stop. I don't see anything in here to suggest that the OpenVPN Service itself was even aware of the problem going on?

Sun Oct 17 18:26:27 2010 OpenVPN 2.1.3 i686-pc-mingw32 [SSL] [LZO2] [PKCS11] built on Aug 20 2010
Sun Oct 17 18:26:27 2010 NOTE: OpenVPN 2.1 requires '--script-security 2' or higher to call user-defined scripts or executables
Sun Oct 17 18:26:27 2010 Diffie-Hellman initialized with 1024 bit key
Sun Oct 17 18:26:28 2010 TLS-Auth MTU parms [ L:1542 D:138 EF:38 EB:0 ET:0 EL:0 ]
Sun Oct 17 18:26:28 2010 Socket Buffers: R=[8192->8192] S=[8192->8192]
Sun Oct 17 18:26:28 2010 ROUTE default_gateway=192.168.255.5
Sun Oct 17 18:26:28 2010 TAP-WIN32 device [OpenVPN Adapter #1] opened: \\.\Global\{09A5E76E-183F-4C7A-8717-E4F857803062}.tap
Sun Oct 17 18:26:28 2010 TAP-Win32 Driver Version 9.7
Sun Oct 17 18:26:28 2010 TAP-Win32 MTU=1500
Sun Oct 17 18:26:28 2010 Notified TAP-Win32 driver to set a DHCP IP/netmask of 10.8.0.1/255.255.255.252 on interface {09A5E76E-183F-4C7A-8717-E4F857803062} [DHCP-serv: 10.8.0.2, lease-time: 31536000]
Sun Oct 17 18:26:28 2010 Sleeping for 10 seconds...
Sun Oct 17 18:26:38 2010 Successful ARP Flush on interface [13] {09A5E76E-183F-4C7A-8717-E4F857803062}
Sun Oct 17 18:26:38 2010 C:\WINDOWS\system32\route.exe ADD 10.8.0.0 MASK 255.255.255.0 10.8.0.2
Sun Oct 17 18:26:38 2010 Warning: route gateway is not reachable on any active network adapters: 10.8.0.2
Sun Oct 17 18:26:38 2010 Route addition via IPAPI failed [adaptive]
Sun Oct 17 18:26:38 2010 Route addition fallback to route.exe
OK!
Sun Oct 17 18:26:39 2010 Data Channel MTU parms [ L:1542 D:1450 EF:42 EB:135 ET:0 EL:0 AF:3/1 ]
Sun Oct 17 18:26:39 2010 UDPv4 link local (bound): 192.168.255.4:1194
Sun Oct 17 18:26:39 2010 UDPv4 link remote: [undef]
Sun Oct 17 18:26:39 2010 MULTI: multi_init called, r=256 v=256
Sun Oct 17 18:26:39 2010 IFCONFIG POOL: base=10.8.0.4 size=62
Sun Oct 17 18:26:39 2010 IFCONFIG POOL LIST
Sun Oct 17 18:26:39 2010 MONSTER.AD3.felines.org,10.8.0.4
Sun Oct 17 18:26:39 2010 GATO.AD3.felines.org,10.8.0.8
Sun Oct 17 18:26:39 2010 Initialization Sequence Completed
Sun Oct 17 19:53:40 2010 TCP/UDP: Closing socket
Sun Oct 17 19:53:40 2010 C:\WINDOWS\system32\route.exe DELETE 10.8.0.0 MASK 255.255.255.0 10.8.0.2
Sun Oct 17 19:53:40 2010 Warning: route gateway is not reachable on any active network adapters: 10.8.0.2
Sun Oct 17 19:53:40 2010 Route deletion via IPAPI failed [adaptive]
Sun Oct 17 19:53:40 2010 Route deletion fallback to route.exe
OK!
Sun Oct 17 19:53:40 2010 Closing TUN/TAP interface
Sun Oct 17 19:53:40 2010 SIGTERM[hard,] received, process exiting


Other information:

IPv6 is disabled on both the physical Ethernet interface of the server, and on the logical TAP interface installed by OpenVPN. There is no IPv6 actually active on the network, except for what the several Windows 7 clients on the network might have by default.

10.8.0.2 is the IP address used by the OpenVPN Service as the DHCP server for the VPN it operates.

The two cached DHCP leases (GATO and MONSTER) are for two physical Windows 7 machines on my LAN, both of which I had used to test the OpenVPN Service when I installed it recently.

No clients are currently configured to attempt to start VPN connections to this OpenVPN Service, and no connection attempts were made to the OpenVPN Service during this event.

The Network Card with network address 00FF09A5E76E mentioned in the error messages is the OpenVPN Service's logical TAP-Win32 Adapter.


Any ideas why this would happen, and how to prevent it in the future?

Thanks!
-Jay

[krzee]

add this to the config

Code: Select all

route-method exe

are you sure it is being started as administrator?
does it work when you start it manually instead of as a service?

[libove]

Thank you for the route-method suggestion, though I'm quite curious to understand how OpenVPN started as a System Service could have a problem using the API to install the route?

And, as I noted originally, this is a System Service, so, yes, it is run with System privileges, and, also as I noted originally, the problem only occurred at boot time when started as the System Service, and did not recur when I manually stopped and restarted the service.

[krzee]

ahh i missed it when you said that it worked when you restarted the service
you want this

Code: Select all

route-delay

the default delay of 30 should be fine

[libove]

Is the route-delay in addition to, or instead of, the route-method?
Thanks,
Jay

[krzee]

you should easily be able to figure out which you need... it is only 2 options to test
you tell me

[libove]

I don't appreciate your attitude krzee.
If all of this were easy to figure out, given that I had read the docs before posting, I likely would have figured it out and not had to post in the first place.
In fact if this were easy, then whatever bug triggered the endless series of Event Log entries would never have occurred.

I've just now re-read the docs. The route-method and route-delay parameters do not appear to be directly related. So I suppose this route-delay is in addition to the route-method, as the route-method was to resolve the minor warning appearing in the log file about the OpenVPN daemon reverting to route.exe, which is not what I asked about in the first place.
I thank you for the useful information about explicitly choosing route.exe over the API to eliminate that harmless log entry, but suggest that you could have been clearer about it not being directly related to the core problem I was asking about when you supplied the information, as it caused later confusion.


Relevant to the bug which filled up my server's Event Log and which was the reason for this conversation:

The documentation for the route-delay option includes:

"Delay n seconds (default=0) after connection establishment, before adding routes. If n is 0, routes will be added immediately upon connection establishment.
If --route-delay is omitted, routes will be added immediately after TUN/TAP device open and --up script execution, before any --user or --group privilege downgrade"

This "Delay n seconds after connection establishment" implies that the default configuration (where no route-delay is specified) the routes will be added "after connection establishment". But at server start time, with no clients configured to connect, what "connection establishment" has occurred?

That could be just vague wording in the doc - because routes are added on the server when it opens the TUN/TAP device to enable listening for connections.

Is that the correct understanding of why a route-delay parameter might help the problem of the IP address lease 0.0.0.0 Event Log entries - by delaying even the server's own core route addition upon starting up until later?

If so, why is it even possible for this race condition to occur? Would that not be a bug in OpenVPN?
And perhaps the documentation should be updated to make it clearer that the route-delay option affects actions within the server at start-up time as well?

Thank you.

[krzee]

for the record, it is *2* options to try in your config... hardly seems worth waiting for someone to answer you, as opposed to trying them.
route-delay waits extra time before adding routes, which seems to be what you need
if you dont like my attitude, i will stop posting on this thread, goodluck

[libove]

As was stated in the original post, and re-stated later, the error occurred a Windows Server boot time.
It is not "*2* options to try in your config". It is 2 options and the time and disruption of a Windows Server restart each time...

[ecrist]

It is just two options, and you don't need to restart the entire server to test things, though in this case, it's going to be your best test.

Based on what's been said, I'd suggest trying the route-delay option first, as that seems to be issue, since things work fine if you restart the service after boot. Just my 2¢.

[libove]

Since the problem only manifested on a server reboot, and not on any manual service restart thereafter, I do not understand how I keep being told "I don't need to restart the server to test it". I stated that in the original post, and again later.

In any case, I have added both the route method option and the route delay option and for other reasons restarted the server, and the problem did not recur. Hopefully, that will be the last of it. Rest assured, if I see that problem again (and I will be checking for it on every reboot for the foreseeable future!) I'll let you know.

Thanks,
Jay