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 = "tes...@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 = " tes...@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} -> tes...@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} -> tes...@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 = "tes...@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 = " tes...@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} -> tes...@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 'tes...@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: [tes...@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} -> tes...@example.com Thu Mar 7 13:38:29 2013 : Info: [exec_reply] expand: %{%{reply:User-Name}:-%{User-Name}} -> tes...@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 <al...@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 >
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html