[Chilli] Ippool exhaustion bug?

Thu Nov 12 08:12:38 UTC 2009

Ok, seeing that nobody seems to have similar problems I'm now posting my 
findings so far: There really /is/ a problem in the chilli code though I 
haven't been able to locate the precise spot where this occurs. So far 
I've carefully inserted / adjusted a whole bunch of log_err(0, ...) 
statements in ippool.c and chilli.c and have the following sample output 
for you, based on the same sample configuration as in my original email 
below (dhcpstart 10.0.0.129, dhcpend 10.0.0.133). It happened after a 
fresh restart of chilli, presumably when the client (my laptop) still 
had a valid lease cached locally:

2009-11-12T09:47:54+02:00 41.144.95.148 coova-chilli[1283]: 
CoovaChilli(ChilliSpot) 1.0.14. Copyright 2002-2005 Mondru AB. Licensed 
under GPL. Copyright 2006-2009 Coova Technologies <support at coova.com>. 
Licensed under GPL. See http://coova.org/ for details.
2009-11-12T09:47:54+02:00 41.144.95.148 coova-chilli[1283]: tun.c: 497: 
TX queue length set to 100
2009-11-12T09:47:54+02:00 41.144.95.148 kernel: device br-lan entered 
promiscuous mode
2009-11-12T09:47:56+02:00 41.144.95.148 coova-chilli[1283]: chilli.c: 
1418: cb_tun_ind: trying to allocate newip
2009-11-12T09:47:56+02:00 41.144.95.148 coova-chilli[1283]: ippool.c: 
334: Requesting new static ip: 10.0.0.131
2009-11-12T09:47:56+02:00 41.144.95.148 coova-chilli[1283]: ippool.c: 
427: In ippool_newip just allocated dynamic address from pool:
2009-11-12T09:47:56+02:00 41.144.95.148 coova-chilli[1283]: ippool.c: 
34: Listsize 132, Firstdyn 0, Lastdyn 3, Firststat 4, Laststat 131
2009-11-12T09:47:56+02:00 41.144.95.148 coova-chilli[1283]: ippool.c: 
43: Unit 0 inuse 0 prev 1431469324 next 1 addr 10.0.0.129
2009-11-12T09:47:56+02:00 41.144.95.148 coova-chilli[1283]: ippool.c: 
43: Unit 1 inuse 0 prev 0 next 3 addr 10.0.0.130
2009-11-12T09:47:56+02:00 41.144.95.148 coova-chilli[1283]: ippool.c: 
43: Unit 2 inuse 1 prev 1431469324 next 1431469324 addr 10.0.0.131
2009-11-12T09:47:56+02:00 41.144.95.148 coova-chilli[1283]: ippool.c: 
43: Unit 3 inuse 0 prev 1 next 1431469324 addr 10.0.0.132

The above shows that cb_tun_ind() function allocates a "static" ip 
(.131) from the dynamic pool BEFORE the dhcp request is even registered:

2009-11-12T09:48:00+02:00 41.144.95.148 coova-chilli[1283]: chilli.c: 
3015: New DHCP request from MAC=00-11-22-33-44-55
2009-11-12T09:48:00+02:00 41.144.95.148 coova-chilli[1283]: ippool.c: 
334: Requesting new static ip: 0.0.0.0
2009-11-12T09:48:00+02:00 41.144.95.148 coova-chilli[1283]: ippool.c: 
334: Requesting new dynamic ip: 0.0.0.0
2009-11-12T09:48:00+02:00 41.144.95.148 coova-chilli[1283]: ippool.c: 
427: In ippool_newip just allocated dynamic address from pool:
2009-11-12T09:48:00+02:00 41.144.95.148 coova-chilli[1283]: ippool.c: 
34: Listsize 132, Firstdyn 1, Lastdyn 3, Firststat 4, Laststat 131
2009-11-12T09:48:00+02:00 41.144.95.148 coova-chilli[1283]: ippool.c: 
43: Unit 0 inuse 1 prev 1431469324 next 1431469324 addr 10.0.0.129
2009-11-12T09:48:00+02:00 41.144.95.148 coova-chilli[1283]: ippool.c: 
43: Unit 1 inuse 0 prev 1431469324 next 3 addr 10.0.0.130
2009-11-12T09:48:00+02:00 41.144.95.148 coova-chilli[1283]: ippool.c: 
43: Unit 2 inuse 1 prev 1431469324 next 1431469324 addr 10.0.0.131
2009-11-12T09:48:00+02:00 41.144.95.148 coova-chilli[1283]: ippool.c: 
43: Unit 3 inuse 0 prev 1 next 1431469324 addr 10.0.0.132

Somehow the normal log message "Client MAC=00-11-22-33-44-55 assigned IP 
10.0.0.129" is missing but you can tell that only in the above piece did 
the real dynamic ip allocation happen. I've set "lease 60" in my 
chilli.conf for debugging purposes so when the ip wasn't renewed in time 
1.5 min later chilli releases the lease and frees the dynamic ip:

2009-11-12T09:49:24+02:00 41.144.95.148 coova-chilli[1283]: chilli.c: 
3146: DHCP addr released by MAC=00-11-22-33-44-55 IP=10.0.0.129
2009-11-12T09:49:24+02:00 41.144.95.148 coova-chilli[1283]: ippool.c: 
504: In ippool_freeip just reinserted ip into list of unused dynamic ips:
2009-11-12T09:49:24+02:00 41.144.95.148 coova-chilli[1283]: ippool.c: 
34: Listsize 132, Firstdyn 1, Lastdyn 0, Firststat 4, Laststat 131
2009-11-12T09:49:24+02:00 41.144.95.148 coova-chilli[1283]: ippool.c: 
43: Unit 0 inuse 0 prev 3 next 1431469324 addr 10.0.0.129
2009-11-12T09:49:24+02:00 41.144.95.148 coova-chilli[1283]: ippool.c: 
43: Unit 1 inuse 0 prev 1431469324 next 3 addr 10.0.0.130
2009-11-12T09:49:24+02:00 41.144.95.148 coova-chilli[1283]: ippool.c: 
43: Unit 2 inuse 1 prev 1431469324 next 1431469324 addr 10.0.0.131
2009-11-12T09:49:24+02:00 41.144.95.148 coova-chilli[1283]: ippool.c: 
43: Unit 3 inuse 0 prev 1 next 0 addr 10.0.0.132

10.0.0.129 has now been successfully freed and returned to the pool 
(inuse 0). But the 10.0.0.131 address assigned by cb_tun_ind remains 
there until the end of days, slowly filling up the pool until it is 
exhausted and nobody can use the hotspot anymore.

Please could somebody (David?) with better knowledge of the source look 
into chilli.c and tell me where the bug is? It will take me forever to 
track it down because my C skills are not that great. Attached is the 
patch relative to 1.0.14 on to enable the above log messages so you can 
reproduce this yourself (just use the below config snippets together 
with "lease 60", start chilli, restart and check out the logs).

Thanks,

Gunther

Gunther Mayer wrote:
> Hi guys,
>
> I've stumbled across the following VERY frustrating problem which is 
> giving me and hundreds of our customers endless grey hair. I have a 
> uamanyip setup with a /24 net, the first /25 subnet of which is for 
> statip and the rest for dynip (implicitly) but specified with 
> dhcpstart and dhcpend for flexibility. After quite a long time, when 
> most ip's have been recycled a fair number of times chilli refuses to 
> hand out any more ip addresses dynamically and chokes with the 
> following appearing ad infinitum in the logs:
>
> 2009-11-09T01:00:14+02:00 coova-chilli[1378]: chilli.c: 3012: New DHCP 
> request from MAC=xx-xx-xx-xx-xx-xx
> 2009-11-09T01:00:14+02:00 coova-chilli[1378]: ippool.c: 397: No more 
> IP addresses available
> 2009-11-09T01:00:14+02:00 coova-chilli[1378]: chilli.c: 332: Failed to 
> allocate either static or dynamic IP address
>
> Of course reproducing my production settings would take forever (about 
> 127 ip addresses between dhcpstart and dhcpend) so I decided to cut it 
> down to the following testing example in chilli.conf:
>
> uamlisten 10.0.0.1
> net 10.0.0.0/24
> dhcpstart 129
> dhcpend 133
> statip 10.0.0.0/25
> uamanyip
>
> That is, 10.0.0.2-10.0.0.127 or 125 ip's are reserved for static 
> ip/anyip clients and 10.0.0.129-10.0.0.132 or 4 ip's for dynamic/dhcp 
> clients. Now to reproduce the ippool bug, connect your linux laptop 
> via cable to the chilli box and do something like
>
> $ dhclient eth0 # should give you 10.0.0.129 first time, then .130 and 
> so on
> $ killall dhclient
> $ ifconfig eth0 0.0.0.0 down
> $ ifconfig eth0 hw ether xx:xx:xx:xx:xx:xx+1
>
> and repeat. Of course the fifth time you do this chilli will 
> legitimately run out of ip addresses because it still has all the 
> other allocated. Until such time that they all time out so wait a bit 
> longer than 10 minutes and start from scratch. Unfortunately I'm no 
> longer able to reproduce this but I could last night, I'll figure out 
> an easy way in time but in the meantime, has anyone seen such problems 
> before? Does anyone have a suggestion?
>
> It looks strongly like some dynamic ip addresses not being properly 
> released in ippool.c but I haven't been able to figure it out.
> This bug has been present in 1.0.13(r199) and 1.0.14(r208), the two 
> I've tested with so far.
>
> Thanks,
>
> Gunther
>

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.coova.org/pipermail/chilli/attachments/20091112/5cb3b2c3/attachment-0001.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: 1.0.14_ippool_debug.patch
Type: text/x-diff
Size: 5078 bytes
Desc: not available
URL: <http://lists.coova.org/pipermail/chilli/attachments/20091112/5cb3b2c3/attachment-0001.patch>