[Chilli] Ippool exhaustion bug?

Thu Nov 12 14:49:33 UTC 2009

Hi Gunther,

You mention one IP being allocated by tun_ind(), which means it's the
result of packets coming into tun0/tap0, which means it's not the
traffic from the end user side of chilli -- rather it's the WAN side.
I'm unclear how this is filling up the pool, however. Is it multiple
entries for the same IP or always allocating new IPs out of tun_ind() ?
Are you using --usetap (if so, try without). Are you narrowing your DHCP
pool only for testing or is your real world IP allocation really a
network smaller than /24 ? 

David

On Thu, 2009-11-12 at 10:12 +0200, Gunther Mayer wrote:
> 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 
> > 
> 
> _______________________________________________
> Chilli mailing list
> Chilli at coova.org
> http://lists.coova.org/cgi-bin/mailman/listinfo/chilli