[Top][All Lists]
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
[Bug-gnu-radius] gnu radius bug in queue processing
|
From: |
Yuriy Vostrikoff |
|
Subject: |
[Bug-gnu-radius] gnu radius bug in queue processing |
|
Date: |
Tue, 18 Jan 2005 17:53:24 +0300 |
|
User-agent: |
Gnus/5.090016 (Oort Gnus v0.16) Emacs/21.2 (gnu/linux) |
Hello.
I found bug in radiusd. radiusd has flaw in its queue processing.
Here is example:
Some ASCII graph:
--------------------------------------------------------------------------------
[NAS ]---[gnu radius address@hidden radius]
[192.168.0.5] [proxing mode ] [192.168.0.8 ]
[192.168.0.5 ]
tcpdump log:
--------------------------------------------------------------------------------
16:54:48.724498 192.168.0.5.1026 > 192.168.0.5.1812: rad-access-req 57 [id 139]
16:54:48.728119 192.168.0.5.1812 > 192.168.0.8.1814: rad-access-req 77 [id 50]
16:54:48.744782 192.168.0.5.1027 > 192.168.0.5.1813: rad-account-req 149 [id
193]
16:54:48.747873 192.168.0.5.1813 > 192.168.0.8.1814: rad-account-req 163 [id
51]
16:54:50.350742 192.168.0.8.1814 > 192.168.0.5.1812: rad-access-reject 40 [id
50]
16:54:50.351667 192.168.0.8.1814 > 192.168.0.5.1813: rad-account-resp 20 [id
51]
16:54:50.357357 192.168.0.5.1812 > 192.168.0.5.1026: rad-access-reject 59 [id
139]
16:54:50.359880 192.168.0.5.1813 > 192.168.0.5.1026: rad-account-resp 20 [id
193]
basicaly bug triggered by two packet from "other radius" recivied in small time
period.
Here it is: packets at 16:54:50.350742 and 16:54:50.351667 timestamps.
radius.debug: (i've deleted unintersting lines and this is already patched
radiusd but it doesn't matter)
--------------------------------------------------------------------------------
Jan 18 16:59:49 radiusd.c:1043:udp_input_handler: 26263 udp input
Jan 18 16:59:49 request.c:156:request_print: 26263 request[d]: ptr:0x8092dc8
stat:RS_WAITING type:R_AUTH state:nil id=238, ipaddr=0xc0a8c805 proxy_id=0
Jan 18 16:59:49 request.c:516:request_handle: 26263 AUTH request 0 added to the
list. 1 requests held.
Jan 18 16:59:49 rpp.c:238:rpp_lookup_ready: 26263 examening pid:26294, ready:1
Jan 18 16:59:49 rpp.c:405:rpp_forward_request: 26263 sending request to 26294
Jan 18 16:59:49 request.c:516:request_handle: 26294 AUTH request 0 added to the
list. 1 requests held.
Jan 18 16:59:49 proxy.c:262:proxy_send_request: 26294 Update id=238,
proxy_id=52, realm=bogus.ru, server_no=0
Jan 18 16:59:49 proxy.c:185:proxy_send_pdu: 26294 Proxying id 238 to c0a8c808
Jan 18 16:59:49 request.c:220:request_respond: 26294 0x80920e8 : completed
Jan 18 16:59:49 rpp.c:526:rpp_request_handler: 26294 notifying the master
Jan 18 16:59:49 rpp.c:572:rpp_input_handler: 26263 updating pid 26294
Jan 18 16:59:49 rpp.c:573:rpp_input_handler: 26263 seting RS_COMPLETED, data =
0x8092178
Jan 18 16:59:49 request.c:533:request_update: 26263 enter, pid=26294, ptr =
0x8092178, status = 1
Jan 18 16:59:49 request.c:545:request_update: 26263 updating request
Jan 18 16:59:49 radius.c:386:radius_req_update: 26263 Update request 238:
proxy_id=52, realm=bogus.ru, server_no=0
Jan 18 16:59:49 request.c:562:request_update: 26263 exit
Jan 18 16:59:49 radiusd.c:1043:udp_input_handler: 26263 udp input
Jan 18 16:59:49 request.c:156:request_print: 26263 request[d]: ptr:0x80920b0
stat:RS_WAITING type:R_ACCT state:nil id=172, ipaddr=0xc0a8c805 proxy_id=0
Jan 18 16:59:49 request.c:516:request_handle: 26263 ACCT request 0 added to the
list. 2 requests held.
Jan 18 16:59:49 request.c:516:request_handle: 26294 ACCT request 0 added to the
list. 2 requests held.
Jan 18 16:59:49 proxy.c:262:proxy_send_request: 26294 Update id=172,
proxy_id=53, realm=bogus.ru, server_no=0
Jan 18 16:59:49 proxy.c:185:proxy_send_pdu: 26294 Proxying id 172 to c0a8c808
Jan 18 16:59:49 request.c:220:request_respond: 26294 0x8092478 : completed
Jan 18 16:59:49 request.c:156:request_print: 26294 request[r]: ptr:0x8092478
stat:RS_COMPLETED type:R_ACCT state:nil id=172, ipaddr=0xc0a8c805 proxy_id=53
Jan 18 16:59:49 rpp.c:526:rpp_request_handler: 26294 notifying the master
Jan 18 16:59:49 rpp.c:572:rpp_input_handler: 26263 updating pid 26294
Jan 18 16:59:49 rpp.c:573:rpp_input_handler: 26263 seting RS_COMPLETED, data =
0x8093f80
Jan 18 16:59:49 request.c:533:request_update: 26263 enter, pid=26294, ptr =
0x8093f80, status = 1
Jan 18 16:59:49 request.c:545:request_update: 26263 updating request
Jan 18 16:59:49 radius.c:386:radius_req_update: 26263 Update request 172:
proxy_id=53, realm=bogus.ru, server_no=0
Jan 18 16:59:49 request.c:562:request_update: 26263 exit
So, master got both packets from NAS and successfully proxied them.
It`s queue is:
ptr:0x8092dc8 stat:RS_COMPLETED type:R_AUTH state:nil ipaddr=0xc0a8c805
proxy_id=52
ptr:0x80920b0 stat:RS_COMPLETED type:R_ACCT state:nil ipaddr=0xc0a8c805
proxy_id=53
Jan 18 16:59:50 radiusd.c:1043:udp_input_handler: 26263 udp input
Jan 18 16:59:50 request.c:156:request_print: 26263 request[d]: ptr:0x80935c8
stat:RS_WAITING type:R_AUTH state:nil id=52, ipaddr=0xc0a8c808 proxy_id=0
Jan 18 16:59:50 proxy.c:157:proxy_cmp: 26263 (old=data) id 238 52, ipaddr
0xc0a8c805 0xc0a8c808, proxy_id 52 0, server_addr 0xc0a8c808 0
Jan 18 16:59:50 proxy.c:160:proxy_cmp: 26263 EQUAL!!!
Jan 18 16:59:50 request.c:476:request_handle: 26263 AUTH proxy reply. Process
26294
Jan 18 16:59:50 rpp.c:405:rpp_forward_request: 26263 sending request to 26294
Master recieved AUTH proxy reply.
Jan 18 16:59:50 radiusd.c:1043:udp_input_handler: 26263 udp input
Jan 18 16:59:50 request.c:156:request_print: 26263 request[d]: ptr:0x8093730
stat:RS_WAITING type:R_ACCT state:nil id=53, ipaddr=0xc0a8c808 proxy_id=0
Jan 18 16:59:50 proxy.c:157:proxy_cmp: 26263 (old=data) id 172 53, ipaddr
0xc0a8c805 0xc0a8c808, proxy_id 53 0, server_addr 0xc0a8c808 0
Jan 18 16:59:50 proxy.c:160:proxy_cmp: 26263 EQUAL!!!
Jan 18 16:59:50 request.c:156:request_print: 26263 request[h]: ptr:0x8093730
stat:RS_WAITING type:R_ACCT state:RCMP_PROXY id=53, ipaddr=0xc0a8c808 proxy_id=0
Jan 18 16:59:50 rpp.c:312:rpp_ready: 26263 none ready child found
Jan 18 16:59:50 request.c:484:request_handle: 26263 Proxy ACCT request 26294
added to the list. 3 requests held.
Master recieved ACCT proxy reply, but corresponding child is busy, so it put it
in queue.
Jan 18 16:59:50 request.c:448:request_handle: 26294 start
Jan 18 16:59:50 request.c:156:request_print: 26294 request[i]: ptr:0x8092648
stat:RS_COMPLETED type:R_AUTH state:RCMP_NE id=52, ipaddr=0xc0a8c808 proxy_id=0
Jan 18 16:59:50 proxy.c:157:proxy_cmp: 26294 (old=data) id 238 52, ipaddr
0xc0a8c805 0xc0a8c808, proxy_id 52 0, server_addr 0xc0a8c808 0
Jan 18 16:59:50 proxy.c:160:proxy_cmp: 26294 EQUAL!!!
Jan 18 16:59:50 request.c:469:request_handle: 26294 AUTH proxy reply. Process 0
Jan 18 16:59:50 rpp.c:526:rpp_request_handler: 26294 notifying the master
Jan 18 16:59:50 rpp.c:572:rpp_input_handler: 26263 updating pid 26294
Jan 18 16:59:50 rpp.c:573:rpp_input_handler: 26263 seting RS_COMPLETED, data =
0x8090fd8
Jan 18 16:59:50 request.c:533:request_update: 26263 enter, pid=26294, ptr =
0x8090fd8, status = 1
Jan 18 16:59:50 request.c:562:request_update: 26263 exit
Here fun starts. Child completed AUTH proxy reply and notifies master. Master
queue is:
ptr:0x8092dc8 stat:RS_COMPLETED type:R_AUTH id=238, ipaddr=0xc0a8c805
proxy_id=52
ptr:0x80920b0 stat:RS_COMPLETED type:R_ACCT id=172, ipaddr=0xc0a8c805
proxy_id=53
ptr:0x8093730 stat:RS_PROXY type:R_ACCT id=53, ipaddr=0xc0a8c808 proxy_id=0
rpp.c:rpp_request_handler:
/* Inform the master */
debug(1, ("notifying the master"));
repl.code = RPP_COMPLETE;
repl.size = 0;
rpp_fd_write(rpp_stdout, &repl, sizeof repl, NULL);
Here: repl.size == 0
rpp.c:rpp_input_handler
void *data = NULL;
if (repl.size) {
[.....]
debug(1, ("seting RS_COMPLETED, data = %p", data));
request_update(p->pid, RS_COMPLETED, data);
p->ready = 1;
Here: Since repl.size == 0, data == NULL, so we calling request_update with
data == NULL.
request:c:request_update
itr = iterator_create(request_list);
for (p = grad_iterator_first(itr); p; p = grad_iterator_next(itr)) {
if (p->child_id == pid) {
p->status = status;
if (ptr && request_class[p->type].update)
request_class[p->type].update(p->data, ptr);
}
ptr here is NULL. And radiusd will set for ALL request in queue req->status =
RS_COMPLETED.
Even for ptr:0x8093730 stat:RS_PROXY type:R_ACCT id=53, ipaddr=0xc0a8c808
proxy_id=0
So, ACCT proxy reply will never been sent to NAS. Until it retransit it again.
Next, even if we fix this bug, ACCTrequest in queue has no chancess to be sent
back to NAS
until this child entered in request_handle. It will do so upon resivieng next
request.
I`ve developed patch. It far from perfect, just an example.
diff -uNr orig/radiusd.c patched/radiusd.c
--- orig/radiusd.c Tue Dec 2 14:18:07 2003
+++ patched/radiusd.c Mon Jan 17 15:42:40 2005
@@ -1040,7 +1040,8 @@
fd,
(struct sockaddr_in*)&sa,
recv_buffer, size);
-
+ debug(1, ("udp input"));
+ request_print("d", req, NULL);
if (request_handle(req,
spawn_flag ?
rpp_forward_request : request_respond))
diff -uNr orig/request.c patched/request.c
--- orig/request.c Sat Nov 8 15:09:17 2003
+++ patched/request.c Tue Jan 18 16:09:25 2005
@@ -73,6 +73,104 @@
/* ************************* General-purpose functions ********************* */
+
+struct request_closure {
+ int type; /* Type of the request */
+ void *data; /* Request contents */
+ void *rawdata; /* Request raw data */
+ size_t rawsize; /* Size thereof */
+ time_t curtime; /* Current timestamp */
+ int (*handler)(REQUEST *); /* Handler function */
+ /* Output: */
+ int state; /* Request compare state */
+ REQUEST *orig; /* Matched request (for proxy requests) */
+ size_t request_count; /* Total number of requests */
+ size_t request_type_count; /* Number of requests of this type */
+};
+
+void
+request_print(char* pfx, REQUEST *req, void *clos)
+{
+ RADIUS_REQ *rr = req->data;
+ struct request_closure *rp = clos;
+ char *status;
+ char *type;
+ char *state;
+ char add_info[256];
+
+ if(!req)
+ debug(1, ("request: ptr(nil)"));
+
+ switch (req->status) {
+ case RS_WAITING:
+ status = "RS_WAITING";
+ break;
+ case RS_COMPLETED:
+ status = "RS_COMPLETED";
+ break;
+ case RS_PROXY:
+ status = "RS_PROXY";
+ break;
+ case RS_XMIT:
+ status = "RS_XMIT";
+ }
+
+ switch (req->type) {
+ case R_NONE:
+ type = "R_NONE";
+ break;
+ case R_AUTH:
+ type = "R_AUTH";
+ break;
+ case R_ACCT:
+ type = "R_ACCT";
+ break;
+ case R_SNMP:
+ type = "R_SNMP";
+ break;
+ case R_MAX:
+ type = "R_MAX";
+ }
+
+ if(rp) {
+ switch (rp->state) {
+ case RCMP_NE:
+ state = "RCMP_NE";
+ break;
+ case RCMP_EQ:
+ state = "RCMP_EQ";
+ break;
+ case RCMP_PROXY:
+ state = "RCMP_PROXY";
+ break;
+ }
+ } else
+ state = "nil";
+ if(req->type == R_AUTH ||
+ req->type == R_ACCT)
+ sprintf(add_info, "id=%d, ipaddr=%#8x proxy_id=%d", rr->id, rr->ipaddr,
rr->server_id);
+ else
+ add_info[0] = 0;
+
+ debug(1, ("request[%s]: ptr:%p stat:%s type:%s state:%s %s",
+ pfx, req, status, type, state, add_info));
+}
+
+
+int
+request_print1(void *data, void *clos)
+{
+ REQUEST *req = data;
+ request_print("", req, clos);
+ return 0;
+}
+void
+request_print_list(RAD_LIST *request_list)
+{
+ if (request_list)
+ list_iterate(request_list, request_print1, NULL);
+}
+
REQUEST *
request_create(int type, int fd, struct sockaddr_in *sa,
u_char *buf, size_t bufsize)
@@ -119,6 +217,8 @@
{
int rc = request_class[req->type].respond(req);
req->status = RS_COMPLETED;
+ debug(1, ("%p : completed", req));
+ request_print("r", req, NULL);
return rc;
}
@@ -149,6 +249,7 @@
if (rpp_ready(req->child_id)) {
rpp_forward_request(req);
req->status = RS_COMPLETED;
+ debug(1, ("%p : completed", req));
return 0;
} else {
req->status = RS_XMIT;
@@ -169,19 +270,7 @@
return request_forward(req);
}
-struct request_closure {
- int type; /* Type of the request */
- void *data; /* Request contents */
- void *rawdata; /* Request raw data */
- size_t rawsize; /* Size thereof */
- time_t curtime; /* Current timestamp */
- int (*handler)(REQUEST *); /* Handler function */
- /* Output: */
- int state; /* Request compare state */
- REQUEST *orig; /* Matched request (for proxy requests) */
- size_t request_count; /* Total number of requests */
- size_t request_type_count; /* Number of requests of this type */
-};
+
static int
_request_iterator(void *item, void *clos)
@@ -189,6 +278,7 @@
REQUEST *req = item;
struct request_closure *rp = clos;
+ request_print("i", req, rp);
if (req->status == RS_COMPLETED) {
if (req->timestamp + request_class[req->type].cleanup_delay
<= rp->curtime) {
@@ -240,6 +330,7 @@
return 0;
if (req->type == rp->type) {
+ debug(1, ("comparing %d", req->type));
rp->state = request_cmp(req, rp->data);
switch (rp->state) {
case RCMP_EQ:
@@ -265,6 +356,77 @@
return 0;
}
+
+
+static int
+_pending_iterator(void *item, void *clos)
+{
+ REQUEST *req = item;
+ struct request_closure *rp = clos;
+
+ request_print("i", req, rp);
+ if (req->status == RS_COMPLETED) {
+ if (req->timestamp + request_class[req->type].cleanup_delay
+ <= rp->curtime) {
+ debug(1, ("deleting completed %s request",
+ request_class[req->type].name));
+ list_remove(request_list, req, NULL);
+ request_free(req);
+ return 0;
+ }
+ } else if (req->status == RS_PROXY) {
+ debug(20, ("found pending proxy request"));
+ if (!spawn_flag || rpp_ready(req->child_id)) {
+ debug(1, ("%s proxy reply. Process %lu",
+ request_class[req->type].name,
+ (u_long) req->child_id));
+ (*rp->handler)(req);
+ list_remove(request_list, req, NULL);
+ request_free(req);
+ } else if (req->timestamp + request_class[req->type].ttl
+ <= rp->curtime) {
+ radlog(L_NOTICE,
+ _("Proxy %s request expired in queue"),
+ request_class[req->type].name);
+ list_remove(request_list, req, NULL);
+ request_free(req);
+ }
+ } else {
+ if (req->status == RS_XMIT && request_forward(req) == 0)
+ return 0;
+
+ if (req->timestamp + request_class[req->type].ttl
+ <= rp->curtime) {
+
+ if (req->status == RS_XMIT)
+ req->status = RS_COMPLETED;
+ else if (rpp_kill(req->child_id, SIGKILL) == 0)
+ radlog(L_NOTICE,
+ _("Killing unresponsive %s child %lu"),
+ request_class[req->type].name,
+ (unsigned long) req->child_id);
+ }
+ return 0;
+ }
+ return 0;
+}
+
+void
+request_process_pending(int (*handler)(REQUEST *))
+{
+ struct request_closure rc;
+ rc.handler = handler;
+ time(&rc.curtime);
+
+
+ debug(1, ("start"));
+ request_print_list(request_list);
+ debug(1, ("processing"));
+
+ if (request_list)
+ list_iterate(request_list, _pending_iterator, &rc);
+}
+
int
request_handle(REQUEST *req, int (*handler)(REQUEST *))
{
@@ -283,11 +445,17 @@
time(&rc.curtime);
rc.request_count = rc.request_type_count = 0;
+ debug(1, ("start"));
+ request_print("i", req, &rc);
+ request_print_list(request_list);
+ debug(1, ("processing"));
+
if (!request_list)
request_list = list_create();
else
list_iterate(request_list, _request_iterator, &rc);
+ request_print("h", req, &rc);
switch (rc.state) {
case RCMP_EQ: /* duplicate */
return 1;
@@ -301,6 +469,7 @@
(u_long) req->child_id));
(*handler)(req);
} else {
+ debug(1, ("spawn_flag:% child_id:%", spawn_flag,
req->child_id));
if (!spawn_flag || rpp_ready(req->child_id)) {
debug(1, ("%s proxy reply. Process %lu",
request_class[req->type].name,
@@ -314,6 +483,7 @@
(u_long) req->child_id,
rc.request_count+1));
list_append(request_list, req);
+ request_print_list(request_list);
return 0;
}
}
@@ -352,21 +522,40 @@
return 1;
}
+#define RPP_COMPLETE 0 /* Completion reply */
+#define RPP_UPDATE 1 /* Update reply */
void
-request_update(pid_t pid, int status, void *ptr)
+request_update(pid_t pid, int status, void *ptr, int rpp_code)
{
REQUEST *p;
ITERATOR *itr;
- debug(100,("enter, pid=%lu, ptr = %p", (unsigned long)pid, ptr));
+ debug(100,("enter, pid=%lu, ptr = %p, status = %d", (unsigned long)pid,
ptr, status));
itr = iterator_create(request_list);
if (!itr)
return;
for (p = iterator_first(itr); p; p = iterator_next(itr)) {
if (p->child_id == pid) {
- p->status = status;
- if (ptr && request_class[p->type].update)
- request_class[p->type].update(p->data, ptr);
+ if(rpp_code == RPP_UPDATE) {
+ RADIUS_REQ *req = p->data;
+ RADIUS_UPDATE *upd = ptr;
+ if (ptr && req->id == upd->id) {
+ p->status = status;
+ if (ptr &&
request_class[p->type].update) {
+ debug(10, ("updating
request"));
+
request_class[p->type].update(p->data, ptr);
+ }
+ }
+ }
+ if(rpp_code == RPP_COMPLETE) {
+ if (ptr) {
+ if(memcmp(ptr, p->rawdata, p->rawsize)
== 0) {
+ debug(1, ("contents equal, set
new status: %d", status));
+ p->status = status;
+ }
+ }
+
+ }
}
}
iterator_destroy(&itr);
diff -uNr orig/rpp.c patched/rpp.c
--- orig/rpp.c Sat Nov 8 15:09:18 2003
+++ patched/rpp.c Tue Jan 18 15:57:37 2005
@@ -227,19 +227,26 @@
ITERATOR *itr = iterator_create(process_list);
for (p = iterator_first(itr); p && !p->ready;
p = iterator_next(itr))
- ;
+ if(p) debug(10, ("examening pid:%d, ready:%d", p->pid,
p->ready));
+ else debug(10, ("examening p:nil"));
iterator_destroy(&itr);
} else {
process_list = list_create();
p = NULL;
}
+ if(p) debug(10, ("examening pid:%d, ready:%d", p->pid, p->ready));
+ else debug(10, ("examening p:nil"));
if (!p) {
rpp_proc_t proc;
- if (list_count(process_list) == max_children)
- return NULL;
- if (rpp_start_process(&proc, proc_main, data))
+ if (list_count(process_list) == max_children) {
+ debug(1, ("maximum childer reached"));
return NULL;
+ }
+ if (rpp_start_process(&proc, proc_main, data)) {
+ debug(1, ("cannot spawn child"));
+ return NULL;
+ }
radiusd_register_input_fd("rpp", proc.p[0], NULL);
p = emalloc(sizeof(*p));
*p = proc;
@@ -285,7 +292,8 @@
int
rpp_ready(pid_t pid)
{
- if (pid == 0) {
+ debug(10, ("entered. pid:%d", pid));
+ if (pid == 0) {
if (rpp_lookup_ready(rpp_request_handler, NULL))
return 1;
} else {
@@ -301,6 +309,7 @@
if (p && p->ready)
return 1;
}
+ debug(10, ("none ready child found"));
return 0;
}
@@ -512,14 +521,17 @@
data, frq.size);
req->status = RS_COMPLETED;
rc = request_handle(req, request_respond);
-
+
/* Inform the master */
debug(1, ("notifying the master"));
repl.code = RPP_COMPLETE;
- repl.size = 0;
+ repl.size = datasize;
rpp_fd_write(1, &repl, sizeof repl, NULL);
- if (rc)
- request_free(req);
+ rpp_fd_write(1, data, datasize, NULL);
+
+ if (rc)
+ request_free(req);
+
}
return 0;
}
@@ -558,8 +570,12 @@
if (p) {
debug(1, ("updating pid %d", p->pid));
- p->ready = 1;
- request_update(p->pid, RS_COMPLETED, data);
+ debug(1, ("seting RS_COMPLETED, data = %p", data));
+ request_update(p->pid, RS_COMPLETED, data, repl.code);
+ p->ready = 1;
+ /* process pending request, that have been recivied
during
+ processing packet */
+ request_process_pending(request_respond);
}
efree(data);
} else if (sz != 0) {
--
Mon at phobos.loc
Der kalte Mond in voller Pracht...
The Moon is Waxing Gibbous (63% of Full)
| [Prev in Thread] |
Current Thread |
[Next in Thread] |
- [Bug-gnu-radius] gnu radius bug in queue processing,
Yuriy Vostrikoff <=