<!DOCTYPE html PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN">
<html>
<head>
<meta content="text/html;charset=ISO-8859-1" http-equiv="Content-Type">
<title></title>
</head>
<body bgcolor="#ffffff" text="#000000">
Ok, seeing that nobody seems to have similar problems I'm now posting
my findings so far: There really <i>is</i> 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:<br>
<br>
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
<a class="moz-txt-link-rfc2396E" href="mailto:support@coova.com"><support@coova.com></a>. Licensed under GPL. See <a class="moz-txt-link-freetext" href="http://coova.org/">http://coova.org/</a>
for details.<br>
2009-11-12T09:47:54+02:00 41.144.95.148 coova-chilli[1283]: tun.c: 497:
TX queue length set to 100<br>
2009-11-12T09:47:54+02:00 41.144.95.148 kernel: device br-lan entered
promiscuous mode<br>
2009-11-12T09:47:56+02:00 41.144.95.148 coova-chilli[1283]: chilli.c:
1418: cb_tun_ind: trying to allocate newip<br>
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<br>
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:<br>
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<br>
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<br>
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<br>
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<br>
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<br>
<br>
The above shows that cb_tun_ind() function allocates a "static" ip
(.131) from the dynamic pool BEFORE the dhcp request is even registered:<br>
<br>
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<br>
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<br>
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<br>
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:<br>
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<br>
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<br>
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<br>
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<br>
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<br>
<br>
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:<br>
<br>
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<br>
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:<br>
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<br>
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<br>
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<br>
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<br>
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<br>
<br>
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.<br>
<br>
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).<br>
<br>
Thanks,<br>
<br>
Gunther<br>
<br>
Gunther Mayer wrote:
<blockquote cite="mid:4AF7F18E.4000502@gmail.com" type="cite">Hi guys,
<br>
<br>
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:
<br>
<br>
2009-11-09T01:00:14+02:00 coova-chilli[1378]: chilli.c: 3012: New DHCP
request from MAC=xx-xx-xx-xx-xx-xx
<br>
2009-11-09T01:00:14+02:00 coova-chilli[1378]: ippool.c: 397: No more IP
addresses available
<br>
2009-11-09T01:00:14+02:00 coova-chilli[1378]: chilli.c: 332: Failed to
allocate either static or dynamic IP address
<br>
<br>
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:
<br>
<br>
uamlisten 10.0.0.1
<br>
net 10.0.0.0/24
<br>
dhcpstart 129
<br>
dhcpend 133
<br>
statip 10.0.0.0/25
<br>
uamanyip
<br>
<br>
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
<br>
<br>
$ dhclient eth0 # should give you 10.0.0.129 first time, then .130 and
so on
<br>
$ killall dhclient
<br>
$ ifconfig eth0 0.0.0.0 down
<br>
$ ifconfig eth0 hw ether xx:xx:xx:xx:xx:xx+1
<br>
<br>
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?
<br>
<br>
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.
<br>
This bug has been present in 1.0.13(r199) and 1.0.14(r208), the two
I've tested with so far.
<br>
<br>
Thanks,
<br>
<br>
Gunther
<br>
<br>
</blockquote>
<br>
</body>
</html>