[SRU] "Unable to set up timer: out of range" caused by bad 64_bit timer

dhcpd fails after a while with:

Feb 11 17:19:18 pent dhcpd: Timeout requested too large reducing to 2^^32-1
Feb 11 17:19:18 pent dhcpd: Unable to set up timer: out of range
Feb 11 17:19:18 pent dhcpd[29451]: Timeout requested too large reducing to 2^^32-1
Feb 11 17:19:18 pent dhcpd:
Feb 11 17:19:18 pent dhcpd[29451]: Unable to set up timer: out of range

dhcp-4.2.3-6.P2.fc16.x86_64

Removing or modifying lease options below seems to make no difference. I don't know of a work-around.

dhcpd.conf is:

ddns-update-style interim;
authoritative;
ignore client-updates;

subnet 192.168.0.0 netmask 255.255.255.0 {
}

subnet 192.168.1.0 netmask 255.255.255.0 {

# --- default gateway
 option routers 192.168.1.1;
 option subnet-mask 255.255.255.0;

 option nis-domain "localdomain";
 option domain-name "localdomain";
 option domain-name-servers 8.8.8.8;

# option time-offset -18000; # Eastern Standard Time

# option ip-forwarding off;

 default-lease-time infinite;
 max-lease-time infinite;

 host rent {
# hardware ethernet 0:c0:9f:66:fa:fd;
# hardware ethernet 0:0b:6b:4c:40:52;
  hardware ethernet 0:1a:6b:6a:21:5b;
# hardware ethernet 00:1b:77:5a:50:7b;
  fixed-address 192.168.1.3;
  option host-name "rent";
 }

 host argument {
  hardware ethernet 00:12:3f:eb:7f:8f;
  fixed-address 192.168.1.4;
  option host-name "argument";
 }

 host sent {
  hardware ethernet 00:1c:bf:42:fb:8a;
  fixed-address 192.168.1.8;
  option host-name "sent";
 }

 host went {
  hardware ethernet 00:0f:b5:9f:c3:78;
  fixed-address 192.168.1.100;
  option host-name "went";
 }

 host parent {
  hardware ethernet b8:ff:61:11:cc:34;
  fixed-address 192.168.1.5;
  option host-name "parent";
 }

 range 192.168.1.9 192.168.1.90;
}

It looks like the client with the request is an Android HTC phone.

In fact, if this really is dhcpd dying due to a bad request, this is a big security hole.

OK, marking as "Security Sensitive" for now. I'll look at the problem tomorrow.

Good news first: The problem is in code (common/dispatch.c:add_timeout()) that was newly added in 4.2.0 so no RHEL version is affected.

We already once had a problem (bug #628258) with this part of code.
I reported the fix upstream but they chose a different solution, which obviously hasn't been perfect.
Their fix was released in 4.2.1b1 with this comment in changelog:
- Limit the timeout period allowed in the dispatch code to 2^^32-1 seconds.
  Thanks to a report from Jiri Popelka at Red Hat.
  [ISC-Bugs #22033], [Red Hat Bug #628258]

John,

thank you for the report. It took me some time to get to it because from the description I hadn't been aware of the fact that the server crashes.

Anyway this really looks like a security problem and to narrow it down some packet dump is crucial (we need to see the message that came from the client before server crashes). Are you able to get one ? You can use wireshark-gnome or tcpdump. Thanks again.

I can, though it will probably be tomorrow at the earliest.

In the meantime I'm using dnsmasq as a workaround.

I've added some debugging outputs to the dhcpd code so it should write out values of some important variables before the crash.

Download it from here http://jpopelka.fedorapeople.org/789601/dhcpd
and make it executable (chmod +x dhcpd).

You could either replace /usr/sbin/dhcpd with it (restore SELinux context with 'restorecon -Fvv /usr/sbin/dhcpd') or simply leave it wherever you want and run it (as root) with /path/to/dhcpd -d [<interface>]

Feb 16 01:54:06 pent dhcpd: Timeout requested too large reducing to 2^^32-1
Feb 16 01:54:06 pent dhcpd: when->tv_sec: 0x4f466e6c (5624983148)
Feb 16 01:54:06 pent dhcpd: when->tv_usec: 0x0 (0)
Feb 16 01:54:06 pent dhcpd: cur_tv.tv_sec: 0x4f3c61be (1329357246)
Feb 16 01:54:06 pent dhcpd: cur_tv.tv_usec: 0x32e58 (208472)
Feb 16 01:54:06 pent dhcpd: sec: 0xffffffff (4294967295)
Feb 16 01:54:06 pent dhcpd: sec & 0xFFFFFFFF: 0xffffffff (4294967295)
Feb 16 01:54:06 pent dhcpd: usec: 0x0 (0)
Feb 16 01:54:06 pent dhcpd: interval.seconds: 0xffffffff (4294967295)
Feb 16 01:54:06 pent dhcpd: interval.nanoseconds: 0x0 (0)
Feb 16 01:54:06 pent dhcpd: expires.seconds: 0xccec5a98 (3438041752)
Feb 16 01:54:06 pent dhcpd: expires.nanoseconds: 0x7f0c (32524)
Feb 16 01:54:06 pent dhcpd: Unable to set up timer: out of range

Created attachment 562491
Provisional patch

I hopefully localized the problem and have a patch.
I locally built the packages but don't know if it's safe tu upload them (not the srpm of course) to a public site like http://jpopelka.fedorapeople.org so John can test them.
Meanwhile there's only the patched dhcpd binary http://jpopelka.fedorapeople.org/789601/dhcpd

Some comment what's (I think) going on is in the patch.
The core fix with comment should be:

dhcp-4.2.3-P2/common/dispatch.c
@@ -246,26 +246,40 @@ void add_timeout (when, where, what, ref
   * the working code use the same values.
   */

+ /*
+ * We need to reduce (to 2^^32-1) the absolute time from an epoch
+ * (i.e. value of when->tv_sec) and not the relative time (value of
+ * sec variable).
+ * In other words, we have to make sure that once the
+ * isc_time_nowplusinterval() adds current time to the given relative
+ * time the result will be less than 2^^32-1.
+ */
+ if (when->tv_sec > DHCP_SEC_MAX) {
+ log_error("Timeout requested too large "
+ "reducing to 2^^32-10");
+ /*
+ * HACK: 9 is some magic number of seconds
+ * because some time goes by between the last call of gettimeofday()
+ * and the one in isc_time_nowplusinterval()
+ * I'm sure the ISC guys will figure out something better ;-)
+ */
+ when->tv_sec = DHCP_SEC_MAX - 9;
+ }
  sec = when->tv_sec - cur_tv.tv_sec;
  usec = when->tv_usec - cur_tv.tv_usec;

Anyway the packet dump (as requested in comment #6) would be still very useful.
So I can try to reproduce it here.

Created attachment 563976
wireshark capture of dhcp discover packet

Thanks, however I can't see anything wrong in the packet and my server (even with your configuration) correctly answers with DHCPOFFER indeed.
Maybe it was some other packet ? You can send the whole packet dump (not just the one message) directly to my email.

It would be also great if you could test the patched dhcpd
http://jpopelka.fedorapeople.org/789601/dhcpd

The patched binary works for me.

Well, even the Discover, Offer, Request, ACK messages in the packet capture you sent to me look good. So when does the server exit ? After it sends the ACK ?

(In reply to comment #14)
> The patched binary works for me.

Great news, thanks.

I'm not sure how to answer your question, I don't know when the server exits beyond "very soon after".

Created attachment 564453
John's packet dump (DHCP messages only).

I went through the packet dump once more but haven't been able to find anything strange (I was hoping to see some big values in some time option or something like that).

I set up a server/client to be as much as possible to John's server/client.
I tried to reproduce the problem here but with no luck.

So although we don't have a reproducer, we know where in the code the problem is, that it's a security problem (DoS) and we have a patch that John confirmed as fixing it.

To security response team:
What's the next step ? Can I report this upstream (<email address hidden>) ?

Created attachment 564454
final patch

I just removed the debug messages, otherwise it's the same as the patch from comment #10.

(In reply to comment #17)
> What's the next step ? Can I report this upstream (<email address hidden>) ?

Yes, you can notify upstream. Please CC s-r-t@ on your report. TY!

So, we have a reproducer. In my case the trick is in
 default-lease-time infinite;
 max-lease-time infinite;
and then
1) let some client get a lease
2) restart the server
and now the first client's request will send the server down.

So it's probably not a security problem after all.

However upstream is asking for some more info.
I already answered what I know and will re-send the questions directly to John
because I don't think we need to use this ticket as an intermediary.

To security-response-team:

Please remove the security flag (I'm not able to do that), see bug #796459, comment #8.

*** Bug 843185 has been marked as a duplicate of this bug. ***

I confirm DHCP server now DHCPACK's the lease and continues to run with:

Jul 26 09:43:02 router dhcpd: Timeout requested too large reducing to 2^^32-10
Jul 26 09:43:02 router dhcpd: DHCPREQUEST for 192.168.25.10 from 52:54:00:eb:e9:fb (station) via eth1
Jul 26 09:43:02 router dhcpd: DHCPACK on 192.168.25.10 to 52:54:00:eb:e9:fb (station) via eth1

Next dhclient run just:

Jul 26 09:44:29 router dhcpd: DHCPREQUEST for 192.168.25.10 from 52:54:00:eb:e9:fb (station) via eth1
Jul 26 09:44:29 router dhcpd: DHCPACK on 192.168.25.10 to 52:54:00:eb:e9:fb (station) via eth1

Using http://koji.fedoraproject.org/koji/taskinfo?taskID=4330107 suggested by jpopelka.

Created attachment 600673
Simpler alternate patch for 64-bit interval calculation bug (see also #662254)

dhcp-4.2.4-9.P1.fc17 has been submitted as an update for Fedora 17.
https://admin.fedoraproject.org/updates/FEDORA-2012-11079/dhcp-4.2.4-9.P1.fc17

dhcp-4.2.3-11.P2.fc16 has been submitted as an update for Fedora 16.
https://admin.fedoraproject.org/updates/FEDORA-2012-11110/dhcp-4.2.3-11.P2.fc16

dhcp-4.2.4-9.P1.fc17 has been pushed to the Fedora 17 stable repository. If problems still persist, please make note of it in this bug report.

dhcp-4.2.3-11.P2.fc16 has been pushed to the Fedora 16 stable repository. If problems still persist, please make note of it in this bug report.