FR_TOKEN userparse(const char *buffer, VALUE_PAIR **first_pair)

{

VALUE_PAIR *vp, *head, **tail;

const char *p;

FR_TOKEN last_token = T_OP_INVALID;

FR_TOKEN previous_token;

* We allow an empty line.

if (buffer[0] == 0)

return T_EOL;

head = NULL;

tail = &head;

p = buffer;

do {

previous_token = last_token;

if ((vp = pairread(&p, &last_token)) == NULL) {

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(first_pair, head);

}

* And return the last token which we read.

return last_token;

}

On Thu, Mar 7, 2013 at 2:15 PM, kao quadrantx <quadrantx@gmail.com> wrote:

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@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@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@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@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@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@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@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@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@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@example.com

Thu Mar 7 13:38:29 2013 : Info: [exec_reply] expand: %{%{reply:User-Name}:-%{User-Name}} -> TEST01@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@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