Freeradius 2.2.0 memory leak issue.
kao quadrantx
quadrantx at gmail.com
Thu Mar 7 07:15:40 CET 2013
Hi,
i rebuild freeradius with the latest updated today (i noticed the
userparse() in valuepair.c has updated) and the memory leak still the same.
(same memory growth in VmRSS and same valgrind log.)
FR_TOKEN userparse(const char *buffer, VALUE_PAIR **list)
{
VALUE_PAIR *vp, *head, **tail;
const char *p;
FR_TOKEN last_token = T_OP_INVALID;
FR_TOKEN previous_token;
VALUE_PAIR_RAW raw;
/*
* We allow an empty line.
*/
if (buffer[0] == 0)
return T_EOL;
head = NULL;
tail = &head;
p = buffer;
do {
raw.l_opand[0] = '\0';
raw.r_opand[0] = '\0';
previous_token = last_token;
last_token = pairread(&p, &raw);
if (last_token == T_OP_INVALID) break;
vp = pairmake(raw.l_opand, raw.r_opand, raw.op);
if (!vp) break;
if (raw.quote == T_DOUBLE_QUOTED_STRING) {
if (pairmark_xlat(vp, raw.r_opand) < 0) {
pairbasicfree(vp);
break;
}
}
*tail = vp;
tail = &((*tail)->next);
} while (*p && (last_token == T_COMMA));
/*
* Don't tell the caller that there was a comment.
*/
if (last_token == T_HASH) {
last_token = previous_token;
}
if (last_token == T_OP_INVALID) {
pairfree(&head);
} else {
pairadd(list, head);
}
/*
* And return the last token which we read.
*/
return last_token;
}
I have checked the radius log with debug_level = 3
There is no error message "Exec-Program-Wait: ...: unparsable reply" that
you mentioned.
Thu Mar 7 13:38:04 2013 : Info: Ready to process requests.
Thu Mar 7 13:38:28 2013 : Debug: Threads: total/active/spare threads =
32/0/32
Thu Mar 7 13:38:28 2013 : Debug: Threads: deleting 1 spare out of 1 spares
Thu Mar 7 13:38:28 2013 : Debug: Thread 32 got semaphore
Thu Mar 7 13:38:28 2013 : Debug: Waking up in 0.9 seconds.
Thu Mar 7 13:38:28 2013 : Debug: Thread 30 got semaphore
Thu Mar 7 13:38:28 2013 : Debug: Thread 32 handling request 0, (1 handled
so far)
Thu Mar 7 13:38:28 2013 : Debug: Thread 30 waiting to be assigned a request
Thu Mar 7 13:38:28 2013 : Info: [<thread>] # Executing section authorize
from file /ramfs/radius/etc/raddb/sites-enabled/default
Thu Mar 7 13:38:28 2013 : Info: [<thread>] +- entering group authorize
{...}
Thu Mar 7 13:38:28 2013 : Info: [detail_log] expand:
/ramfs/radius/var/log/radius/radius.log1 ->
/ramfs/radius/var/log/radius/radius.log1
Thu Mar 7 13:38:28 2013 : Info: [detail_log]
/ramfs/radius/var/log/radius/radius.log1 expands to
/ramfs/radius/var/log/radius/radius.log1
Thu Mar 7 13:38:28 2013 : Info: [detail_log] expand: %t Src-IP-Address =
%{Packet-Src-IP-Address} -> Thu Mar 7 13:38:28 2013 Src-IP-Address =
192.168.1.93
Thu Mar 7 13:38:28 2013 : Info: ++[detail_log] returns ok
Thu Mar 7 13:38:28 2013 : Info: ++[preprocess] returns ok
Thu Mar 7 13:38:28 2013 : Info: ++[chap] returns noop
Thu Mar 7 13:38:28 2013 : Info: ++[mschap] returns noop
Thu Mar 7 13:38:28 2013 : Info: [suffix] Looking up realm "example.com"
for User-Name = "TEST01 at example.com"
Thu Mar 7 13:38:28 2013 : Info: [suffix] No such realm "example.com"
Thu Mar 7 13:38:28 2013 : Info: ++[suffix] returns noop
Thu Mar 7 13:38:28 2013 : Info: [ntdomain] No '\' in User-Name = "
TEST01 at example.com", looking up realm NULL
Thu Mar 7 13:38:28 2013 : Info: [ntdomain] No such realm "NULL"
Thu Mar 7 13:38:28 2013 : Info: ++[ntdomain] returns noop
Thu Mar 7 13:38:28 2013 : Info: [eap] EAP packet type response id 0 length
23
Thu Mar 7 13:38:28 2013 : Info: [eap] No EAP Start, assuming it's an
on-going EAP conversation
Thu Mar 7 13:38:28 2013 : Info: ++[eap] returns updated
Thu Mar 7 13:38:28 2013 : Info: [exec_auth] expand: %{User-Name} ->
TEST01 at example.com
Thu Mar 7 13:38:29 2013 : Debug: Exec-Program output: Proxy-To-Realm = .
Thu Mar 7 13:38:29 2013 : Debug: Exec-Program-Wait: value-pairs:
Proxy-To-Realm = .
Thu Mar 7 13:38:29 2013 : Debug: Exec-Program: returned: 0
Thu Mar 7 13:38:29 2013 : Info: ++[exec_auth] returns ok
Thu Mar 7 13:38:29 2013 : Info: ++[pap] returns noop
Thu Mar 7 13:38:29 2013 : Info: # Executing section pre-proxy from file
/ramfs/radius/etc/raddb/sites-enabled/default
Thu Mar 7 13:38:29 2013 : Info: +- entering group pre-proxy {...}
Thu Mar 7 13:38:29 2013 : Debug: Exec-Program output: NAS-IP-Address :=
10.0.7.71, Called-Station-Id := 00-10-F3-28-12-BC, NAS-Port := 0,
Service-Type := 1, WISPr-Logoff-URL := http://logout
Thu Mar 7 13:38:29 2013 : Debug: Exec-Program-Wait: value-pairs:
NAS-IP-Address := 10.0.7.71, Called-Station-Id := 00-10-F3-28-12-BC,
NAS-Port := 0, Service-Type := 1, WISPr-Logoff-URL := http://logout
Thu Mar 7 13:38:29 2013 : Debug: Exec-Program: returned: 0
Thu Mar 7 13:38:29 2013 : Info: ++[exec_proxy_auth] returns ok
Thu Mar 7 13:38:29 2013 : Info: [attr_filter.pre-proxy] expand: %{Realm}
-> .
Thu Mar 7 13:38:29 2013 : Debug: attr_filter: Matched entry DEFAULT at
line 1
Thu Mar 7 13:38:29 2013 : Info: ++[attr_filter.pre-proxy] returns updated
Thu Mar 7 13:38:29 2013 : Info: Proxying request 0 to home server
10.0.7.70 port 1812
Thu Mar 7 13:38:29 2013 : Debug: Going to the next request
Thu Mar 7 13:38:29 2013 : Debug: Thread 32 waiting to be assigned a request
Thu Mar 7 13:38:29 2013 : Debug: Waking up in 0.9 seconds.
Thu Mar 7 13:38:29 2013 : Debug: Thread 31 got semaphore
Thu Mar 7 13:38:29 2013 : Debug: Thread 31 handling request 0, (1 handled
so far)
Thu Mar 7 13:38:29 2013 : Info: [<thread>] # Executing section post-proxy
from file /ramfs/radius/etc/raddb/sites-enabled/default
Thu Mar 7 13:38:29 2013 : Info: [<thread>] +- entering group post-proxy
{...}
Thu Mar 7 13:38:29 2013 : Info: [eap] No pre-existing handler found
Thu Mar 7 13:38:29 2013 : Info: ++[eap] returns noop
Thu Mar 7 13:38:29 2013 : Info: ++? if ("%{proxy-reply:Packet-Type}" ==
"Access-Challenge")
Thu Mar 7 13:38:29 2013 : Info: expand: %{proxy-reply:Packet-Type} ->
Access-Challenge
Thu Mar 7 13:38:29 2013 : Info: ? Evaluating ("%{proxy-reply:Packet-Type}"
== "Access-Challenge") -> TRUE
Thu Mar 7 13:38:29 2013 : Info: ++? if ("%{proxy-reply:Packet-Type}" ==
"Access-Challenge") -> TRUE
Thu Mar 7 13:38:29 2013 : Info: ++- entering if
("%{proxy-reply:Packet-Type}" == "Access-Challenge") {...}
Thu Mar 7 13:38:29 2013 : Info: [attr_filter.access_challenge] expand:
%{User-Name} -> TEST01 at example.com
Thu Mar 7 13:38:29 2013 : Debug: attr_filter: Matched entry DEFAULT at
line 1
Thu Mar 7 13:38:29 2013 : Info: +++[attr_filter.access_challenge] returns
updated
Thu Mar 7 13:38:29 2013 : Info: ++- if ("%{proxy-reply:Packet-Type}" ==
"Access-Challenge") returns updated
Thu Mar 7 13:38:29 2013 : Info: Finished request 0.
Thu Mar 7 13:38:29 2013 : Debug: Going to the next request
Thu Mar 7 13:38:29 2013 : Debug: Thread 31 waiting to be assigned a request
Thu Mar 7 13:38:29 2013 : Debug: Threads: deleting 1 spare out of 1 spares
Thu Mar 7 13:38:29 2013 : Debug: Waking up in 0.9 seconds.
Thu Mar 7 13:38:29 2013 : Debug: Thread 29 got semaphore
Thu Mar 7 13:38:29 2013 : Debug: Thread 29 handling request 1, (1 handled
so far)
Thu Mar 7 13:38:29 2013 : Debug: Thread 28 got semaphore
Thu Mar 7 13:38:29 2013 : Debug: Thread 28 waiting to be assigned a request
Thu Mar 7 13:38:29 2013 : Info: [<thread>] # Executing section authorize
from file /ramfs/radius/etc/raddb/sites-enabled/default
Thu Mar 7 13:38:29 2013 : Info: [<thread>] +- entering group authorize
{...}
Thu Mar 7 13:38:29 2013 : Info: [detail_log] expand:
/ramfs/radius/var/log/radius/radius.log1 ->
/ramfs/radius/var/log/radius/radius.log1
Thu Mar 7 13:38:29 2013 : Info: [detail_log]
/ramfs/radius/var/log/radius/radius.log1 expands to
/ramfs/radius/var/log/radius/radius.log1
Thu Mar 7 13:38:29 2013 : Info: [detail_log] expand: %t Src-IP-Address =
%{Packet-Src-IP-Address} -> Thu Mar 7 13:38:29 2013 Src-IP-Address =
192.168.1.93
Thu Mar 7 13:38:29 2013 : Info: ++[detail_log] returns ok
Thu Mar 7 13:38:29 2013 : Info: ++[preprocess] returns ok
Thu Mar 7 13:38:29 2013 : Info: ++[chap] returns noop
Thu Mar 7 13:38:29 2013 : Info: ++[mschap] returns noop
Thu Mar 7 13:38:29 2013 : Info: [suffix] Looking up realm "example.com"
for User-Name = "TEST01 at example.com"
Thu Mar 7 13:38:29 2013 : Info: [suffix] No such realm "example.com"
Thu Mar 7 13:38:29 2013 : Info: ++[suffix] returns noop
Thu Mar 7 13:38:29 2013 : Info: [ntdomain] No '\' in User-Name = "
TEST01 at example.com", looking up realm NULL
Thu Mar 7 13:38:29 2013 : Info: [ntdomain] No such realm "NULL"
Thu Mar 7 13:38:29 2013 : Info: ++[ntdomain] returns noop
Thu Mar 7 13:38:29 2013 : Info: [eap] EAP packet type response id 1 length
22
Thu Mar 7 13:38:29 2013 : Info: [eap] No EAP Start, assuming it's an
on-going EAP conversation
Thu Mar 7 13:38:29 2013 : Info: ++[eap] returns updated
Thu Mar 7 13:38:29 2013 : Info: [exec_auth] expand: %{User-Name} ->
TEST01 at example.com
Thu Mar 7 13:38:29 2013 : Debug: Exec-Program output: Proxy-To-Realm = .
Thu Mar 7 13:38:29 2013 : Debug: Exec-Program-Wait: value-pairs:
Proxy-To-Realm = .
Thu Mar 7 13:38:29 2013 : Debug: Exec-Program: returned: 0
Thu Mar 7 13:38:29 2013 : Info: ++[exec_auth] returns ok
Thu Mar 7 13:38:29 2013 : Info: ++[pap] returns noop
Thu Mar 7 13:38:29 2013 : Info: # Executing section pre-proxy from file
/ramfs/radius/etc/raddb/sites-enabled/default
Thu Mar 7 13:38:29 2013 : Info: +- entering group pre-proxy {...}
Thu Mar 7 13:38:29 2013 : Debug: Exec-Program output: NAS-IP-Address :=
10.0.7.71, Called-Station-Id := 00-10-F3-28-12-BC, NAS-Port := 0,
Service-Type := 1, WISPr-Logoff-URL := http://logout
Thu Mar 7 13:38:29 2013 : Debug: Exec-Program-Wait: value-pairs:
NAS-IP-Address := 10.0.7.71, Called-Station-Id := 00-10-F3-28-12-BC,
NAS-Port := 0, Service-Type := 1, WISPr-Logoff-URL := http://logout
Thu Mar 7 13:38:29 2013 : Debug: Exec-Program: returned: 0
Thu Mar 7 13:38:29 2013 : Info: ++[exec_proxy_auth] returns ok
Thu Mar 7 13:38:29 2013 : Info: [attr_filter.pre-proxy] expand: %{Realm}
-> .
Thu Mar 7 13:38:29 2013 : Debug: attr_filter: Matched entry DEFAULT at
line 1
Thu Mar 7 13:38:29 2013 : Info: ++[attr_filter.pre-proxy] returns updated
Thu Mar 7 13:38:29 2013 : Debug: Going to the next request
Thu Mar 7 13:38:29 2013 : Debug: Thread 29 waiting to be assigned a request
Thu Mar 7 13:38:29 2013 : Debug: Waking up in 0.9 seconds.
Thu Mar 7 13:38:29 2013 : Debug: Thread 27 got semaphore
Thu Mar 7 13:38:29 2013 : Debug: Thread 27 handling request 1, (1 handled
so far)
Thu Mar 7 13:38:29 2013 : Info: [<thread>] # Executing section post-proxy
from file /ramfs/radius/etc/raddb/sites-enabled/default
Thu Mar 7 13:38:29 2013 : Info: [<thread>] +- entering group post-proxy
{...}
Thu Mar 7 13:38:29 2013 : Info: [eap] No pre-existing handler found
Thu Mar 7 13:38:29 2013 : Info: ++[eap] returns noop
Thu Mar 7 13:38:29 2013 : Info: ++? if ("%{proxy-reply:Packet-Type}" ==
"Access-Challenge")
Thu Mar 7 13:38:29 2013 : Info: expand: %{proxy-reply:Packet-Type} ->
Access-Accept
Thu Mar 7 13:38:29 2013 : Info: ? Evaluating ("%{proxy-reply:Packet-Type}"
== "Access-Challenge") -> FALSE
Thu Mar 7 13:38:29 2013 : Info: ++? if ("%{proxy-reply:Packet-Type}" ==
"Access-Challenge") -> FALSE
Thu Mar 7 13:38:29 2013 : Info: Found Auth-Type = EAP
Thu Mar 7 13:38:29 2013 : Info: Found Auth-Type = Accept
Thu Mar 7 13:38:29 2013 : Error: Warning: Found 2 auth-types on request
for user 'TEST01 at example.com'
Thu Mar 7 13:38:29 2013 : Info: Auth-Type = Accept, accepting the user
Thu Mar 7 13:38:29 2013 : Auth: Login OK: [TEST01 at example.com/<via
Auth-Type = EAP>] (from client 192.168.0.0/16 port 0 cli 00-19-81-11-07-45)
Thu Mar 7 13:38:29 2013 : Info: # Executing section post-auth from file
/ramfs/radius/etc/raddb/sites-enabled/default
Thu Mar 7 13:38:29 2013 : Info: +- entering group post-auth {...}
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] expand: %{reply:User-Name} ->
TEST01 at example.com
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] expand:
%{%{reply:User-Name}:-%{User-Name}} -> TEST01 at example.com
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] expand: %{NAS-IP-Address} ->
192.168.1.93
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] expand:
%{check:Post-Auth-Type} ->
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] expand:
%{reply:Session-Timeout} -> 1200
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] expand: %{reply:Idle-Timeout}
-> 30
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] expand:
%{reply:Acct-Interim-Interval} ->
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] expand:
%{reply:Acct-Session-ID} ->
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] expand:
%{reply:ZVendor-Byte-Amount-4GB},%{reply:ZVendor-Byte-Amount} -> ,
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] expand:
%{reply:ZVendor-MaxByteIn-4GB},%{reply:ZVendor-MaxByteIn} -> ,
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] expand:
%{reply:ZVendor-MaxByteOut-4GB},%{reply:ZVendor-MaxByteOut} -> ,
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] expand: %{reply:Class[*]} ->
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] expand:
%{reply:WISPr-Bandwidth-Min-Up} ->
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] ... expanding second
conditional
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] expand:
%{reply:WISPr-Bandwidth-Max-Up} ->
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] ... expanding second
conditional
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] expand:
%{%{reply:WISPr-Bandwidth-Min-Up}:-0}:%{%{reply:WISPr-Bandwidth-Max-Up}:-0}
-> 0:0
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] expand:
%{reply:WISPr-Bandwidth-Min-Down} ->
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] ... expanding second
conditional
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] expand:
%{reply:WISPr-Bandwidth-Max-Down} ->
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] ... expanding second
conditional
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] expand:
%{%{reply:WISPr-Bandwidth-Min-Down}:-0}:%{%{reply:WISPr-Bandwidth-Max-Down}:-0}
-> 0:0
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] expand:
%{reply:WISPr-Redirection-URL} ->
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] expand:
%{reply:WISPr-Session-Trerminate-Time} ->
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] expand:
%{reply:WISPr-Session-Terminate-End-Of-Day} ->
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] expand:
%{reply:WISPr-Billing-Class-Of-Service} ->
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] expand:
%{reply:ZVendor-Group} ->
Thu Mar 7 13:38:29 2013 : Info: [exec_reply] expand:
%{reply:Chargeable-User-Identity} ->
Thu Mar 7 13:38:29 2013 : Debug: Exec-Program output: Session-Timeout :=
1200, Idle-Timeout := 30, Acct-Interim-Interval := 300,
WISPr-Bandwidth-Min-Up := 0, WISPr-Bandwidth-Max-Up := 0,
WISPr-Bandwidth-Min-Down := 0, WISPr-Bandwidth-Max-Down := 0
Thu Mar 7 13:38:29 2013 : Debug: Exec-Program-Wait: value-pairs:
Session-Timeout := 1200, Idle-Timeout := 30, Acct-Interim-Interval := 300,
WISPr-Bandwidth-Min-Up := 0, WISPr-Bandwidth-Max-Up := 0,
WISPr-Bandwidth-Min-Down := 0, WISPr-Bandwidth-Max-Down := 0
Thu Mar 7 13:38:29 2013 : Debug: Exec-Program: returned: 0
Thu Mar 7 13:38:29 2013 : Info: ++[exec_reply] returns ok
Thu Mar 7 13:38:29 2013 : Info: Finished request 1.
Thu Mar 7 13:38:29 2013 : Debug: Going to the next request
Thu Mar 7 13:38:29 2013 : Debug: Thread 27 waiting to be assigned a request
Thu Mar 7 13:38:30 2013 : Debug: Waking up in 0.9 seconds.
Thu Mar 7 13:38:31 2013 : Info: Cleaning up request 0 ID 0 with timestamp
+24
Thu Mar 7 13:38:31 2013 : Info: Cleaning up request 1 ID 1 with timestamp
+25
Thu Mar 7 13:38:31 2013 : Info: Ready to process requests.
On Wed, Mar 6, 2013 at 10:08 PM, Alan DeKok <aland at deployingradius.com>wrote:
> kao quadrantx wrote:
> > I try to test with the latest version of freeradius in git 2.x.x and
> > still get the same behavior.
>
> $ git pull
>
> Then rebuild.
>
> > Seems the envp variable in radius_exec_program function (exec.c) not
> clean?
>
> No. It looks like the userparse() function isn't cleaning up properly
> on error.
>
> i.e. your script is writing *invalid* attributes to its output.
> However... only *some* of them are invalid. The server is parsing the
> valid ones, and then stopping when it receives the invalid ones. But...
> it doesn't free the valid ones, even though it doesn't use them.
>
> The solution (other than the bug fix I just committed), is to ensure
> that your external script returns *valid* attributes.
>
> If you look at radiusd.log, you'll probably see tons of:
>
> Exec-Program-Wait: ...: unparsable reply
>
> This indicates that your script is broken. But it shouldn't cause
> issues for the server.
>
> Alan DeKok.
> -
> List info/subscribe/unsubscribe? See
> http://www.freeradius.org/list/users.html
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20130307/0569b90c/attachment-0001.html>
More information about the Freeradius-Users
mailing list