Freeradius 2.2.0 memory leak issue.
Hi, i got the same issue in freeradius memory issue http://freeradius.1045715.n5.nabble.com/Memory-leak-in-FR-2-1-10-and-2-2-0-t... My test ENV: eapol_test with md5 to do AUTH (client) ---------> freeradius 2.2.0 to proxy the client request (proxy) -----------------------------> freeradius 2.2.0 More request more memory (VmRSS) consumed by radiusd (proxy), and the daemon performance will also down. And i use valgrind to log this: ==14786== ==14786== HEAP SUMMARY: ==14786== in use at exit: 172,724 bytes in 2,819 blocks ==14786== total heap usage: 43,388 allocs, 40,569 frees, 5,148,356 bytes allocated ==14786== ==14786== 4 bytes in 1 blocks are definitely lost in loss record 1 of 527 ==14786== at 0x4C23224: malloc (vg_replace_malloc.c:270) ==14786== by 0x633A061: strdup (in /lib/libc-2.9.so) ==14786== by 0x40E641: cf_item_parse (conffile.c:953) ==14786== by 0x41BF4A: listen_parse (listen.c:1953) ==14786== by 0x41C5CA: listen_init (listen.c:2174) ==14786== by 0x438A36: radius_event_init (event.c:3648) ==14786== by 0x425971: main (radiusd.c:332) ==14786== ==14786== 5 bytes in 1 blocks are definitely lost in loss record 3 of 527 ==14786== at 0x4C23224: malloc (vg_replace_malloc.c:270) ==14786== by 0x633A061: strdup (in /lib/libc-2.9.so) ==14786== by 0x40E641: cf_item_parse (conffile.c:953) ==14786== by 0x40EE5C: cf_section_parse (conffile.c:1173) ==14786== by 0x41DE96: switch_users (mainconfig.c:614) ==14786== by 0x41E6B9: read_mainconfig (mainconfig.c:874) ==14786== by 0x4257CD: main (radiusd.c:263) ==14786== ==14786== 368 (136 direct, 232 indirect) bytes in 1 blocks are definitely lost in loss record 477 of 527 ==14786== at 0x4C23224: malloc (vg_replace_malloc.c:270) ==14786== by 0x42B8AF: rad_malloc (util.c:347) ==14786== by 0x41B9BF: listen_alloc (listen.c:1735) ==14786== by 0x41BC83: proxy_new_listener (listen.c:1838) ==14786== by 0x43D514: home_server_create_callback (realms.c:2254) ==14786== by 0x4E45CFA: WalkNodeInOrder (rbtree.c:551) ==14786== by 0x4E45E78: rbtree_walk (rbtree.c:603) ==14786== by 0x43D564: home_server_create_listeners (realms.c:2280) ==14786== by 0x41CA15: listen_init (listen.c:2323) ==14786== by 0x438A36: radius_event_init (event.c:3648) ==14786== by 0x425971: main (radiusd.c:332) ==14786== ==14786== 6,800 bytes in 25 blocks are possibly lost in loss record 522 of 527 ==14786== at 0x4C252BE: calloc (vg_replace_malloc.c:593) ==14786== by 0x40104BE: _dl_allocate_tls (in /lib/ld-2.9.so) ==14786== by 0x5491C14: pthread_create (in /lib/libpthread-2.9.so) ==14786== by 0x42A611: spawn_thread (threads.c:663) ==14786== by 0x42AB1B: thread_pool_init (threads.c:862) ==14786== by 0x438803: radius_event_init (event.c:3575) ==14786== by 0x425971: main (radiusd.c:332) ==14786== ==14786== 37,440 (18,720 direct, 18,720 indirect) bytes in 60 blocks are definitely lost in loss record 526 of 527 ==14786== at 0x4C23224: malloc (vg_replace_malloc.c:270) ==14786== by 0x4E488C8: pairalloc (valuepair.c:72) ==14786== by 0x4E4AFFC: pairmake (valuepair.c:1526) ==14786== by 0x4E4B553: pairread (valuepair.c:1736) ==14786== by 0x4E4B8C4: userparse (valuepair.c:1850) ==14786== by 0x412A7F: radius_exec_program (exec.c:583) ==14786== by 0x6C1A5F5: ??? ==14786== by 0x6C1A71B: ??? ==14786== by 0x421CAB: call_modsingle (modcall.c:304) ==14786== by 0x422AD5: modcall (modcall.c:686) ==14786== by 0x41FCB8: indexed_modcall (modules.c:740) ==14786== by 0x4216FC: module_post_auth (modules.c:1662) ==14786== ==14786== 37,440 bytes in 120 blocks are definitely lost in loss record 527 of 527 ==14786== at 0x4C23224: malloc (vg_replace_malloc.c:270) ==14786== by 0x4E488C8: pairalloc (valuepair.c:72) ==14786== by 0x4E4AFFC: pairmake (valuepair.c:1526) ==14786== by 0x4E4B553: pairread (valuepair.c:1736) ==14786== by 0x4E4B8C4: userparse (valuepair.c:1850) ==14786== by 0x412A7F: radius_exec_program (exec.c:583) ==14786== by 0x6C1A5F5: ??? ==14786== by 0x421CAB: call_modsingle (modcall.c:304) ==14786== by 0x422AD5: modcall (modcall.c:686) ==14786== by 0x41FCB8: indexed_modcall (modules.c:740) ==14786== by 0x4216B4: module_pre_proxy (modules.c:1645) ==14786== by 0x435F6E: successfully_proxied_request (event.c:2230) ==14786== ==14786== LEAK SUMMARY: ==14786== definitely lost: 56,305 bytes in 183 blocks ==14786== indirectly lost: 18,952 bytes in 63 blocks ==14786== possibly lost: 6,800 bytes in 25 blocks ==14786== still reachable: 90,667 bytes in 2,548 blocks ==14786== suppressed: 0 bytes in 0 blocks ==14786== Reachable blocks (those to which a pointer was found) are not shown. ==14786== To see them, rerun with: --leak-check=full --show-reachable=yes ==14786== ==14786== For counts of detected and suppressed errors, rerun with: -v ==14786== Use --track-origins=yes to see where uninitialised values come from ==14786== ERROR SUMMARY: 715158 errors from 470 contexts (suppressed: 201 from 43)
Hi, I try to test with the latest version of freeradius in git 2.x.x and still get the same behavior. Seems the envp variable in radius_exec_program function (exec.c) not clean? PS: my system is 64bit. valgrind log below: ==3043== 13,852 (368 direct, 13,484 indirect) bytes in 2 blocks are definitely lost in loss record 622 of 625 ==3043== at 0x4C23224: malloc (vg_replace_malloc.c:270) ==3043== by 0x5D9A1E1: CRYPTO_malloc (in /lib/libcrypto.so.0.9.8) ==3043== by 0x5B1CD96: ssl_cert_new (in /lib/libssl.so.0.9.8) ==3043== by 0x5B1AC0A: SSL_CTX_new (in /lib/libssl.so.0.9.8) ==3043== by 0x8265DFB: ??? ==3043== by 0x8266817: ??? ==3043== by 0x783D99F: ??? ==3043== by 0x783C802: ??? ==3043== by 0x41F921: find_module_instance (modules.c:612) ==3043== by 0x424712: do_compile_modsingle (modcall.c:1924) ==3043== by 0x424D47: compile_modsingle (modcall.c:2053) ==3043== by 0x420269: load_component_section (modules.c:900) ==3043== ==3043== 62,400 (31,200 direct, 31,200 indirect) bytes in 100 blocks are definitely lost in loss record 624 of 625 ==3043== at 0x4C23224: malloc (vg_replace_malloc.c:270) ==3043== by 0x4E48C6C: pairalloc (valuepair.c:72) ==3043== by 0x4E4B3A9: pairmake (valuepair.c:1526) ==3043== by 0x4E4B900: pairread (valuepair.c:1736) ==3043== by 0x4E4BC71: userparse (valuepair.c:1850) ==3043== by 0x4128E8: radius_exec_program (exec.c:456) ==3043== by 0x6C1D5F5: ??? ==3043== by 0x6C1D71B: ??? ==3043== by 0x421DE3: call_modsingle (modcall.c:304) ==3043== by 0x422BF1: modcall (modcall.c:684) ==3043== by 0x41FDF1: indexed_modcall (modules.c:742) ==3043== by 0x421835: module_post_auth (modules.c:1664) ==3043== ==3043== 62,400 bytes in 200 blocks are definitely lost in loss record 625 of 625 ==3043== at 0x4C23224: malloc (vg_replace_malloc.c:270) ==3043== by 0x4E48C6C: pairalloc (valuepair.c:72) ==3043== by 0x4E4B3A9: pairmake (valuepair.c:1526) ==3043== by 0x4E4B900: pairread (valuepair.c:1736) ==3043== by 0x4E4BC71: userparse (valuepair.c:1850) ==3043== by 0x4128E8: radius_exec_program (exec.c:456) ==3043== by 0x6C1D5F5: ??? ==3043== by 0x421DE3: call_modsingle (modcall.c:304) ==3043== by 0x422BF1: modcall (modcall.c:684) ==3043== by 0x41FDF1: indexed_modcall (modules.c:742) ==3043== by 0x4217ED: module_pre_proxy (modules.c:1647) ==3043== by 0x436979: successfully_proxied_request (event.c:2248) ==3043== ==3043== LEAK SUMMARY: ==3043== definitely lost: 95,310 bytes in 328 blocks ==3043== indirectly lost: 54,672 bytes in 727 blocks ==3043== possibly lost: 0 bytes in 0 blocks ==3043== still reachable: 73,867 bytes in 2,473 blocks ==3043== suppressed: 0 bytes in 0 blocks ==3043== Reachable blocks (those to which a pointer was found) are not shown. ==3043== To see them, rerun with: --leak-check=full --show-reachable=yes ==3043== ==3043== For counts of detected and suppressed errors, rerun with: -v ==3043== Use --track-origins=yes to see where uninitialised values come from ==3043== ERROR SUMMARY: 986273 errors from 479 contexts (suppressed: 201 from 43) On Wed, Mar 6, 2013 at 4:08 PM, kao quadrantx <quadrantx@gmail.com> wrote:
Hi,
i got the same issue in freeradius memory issue http://freeradius.1045715.n5.nabble.com/Memory-leak-in-FR-2-1-10-and-2-2-0-t...
My test ENV:
eapol_test with md5 to do AUTH (client) ---------> freeradius 2.2.0 to proxy the client request (proxy) -----------------------------> freeradius 2.2.0
More request more memory (VmRSS) consumed by radiusd (proxy), and the daemon performance will also down.
And i use valgrind to log this:
==14786== ==14786== HEAP SUMMARY: ==14786== in use at exit: 172,724 bytes in 2,819 blocks ==14786== total heap usage: 43,388 allocs, 40,569 frees, 5,148,356 bytes allocated ==14786== ==14786== 4 bytes in 1 blocks are definitely lost in loss record 1 of 527 ==14786== at 0x4C23224: malloc (vg_replace_malloc.c:270) ==14786== by 0x633A061: strdup (in /lib/libc-2.9.so) ==14786== by 0x40E641: cf_item_parse (conffile.c:953) ==14786== by 0x41BF4A: listen_parse (listen.c:1953) ==14786== by 0x41C5CA: listen_init (listen.c:2174) ==14786== by 0x438A36: radius_event_init (event.c:3648) ==14786== by 0x425971: main (radiusd.c:332) ==14786== ==14786== 5 bytes in 1 blocks are definitely lost in loss record 3 of 527 ==14786== at 0x4C23224: malloc (vg_replace_malloc.c:270) ==14786== by 0x633A061: strdup (in /lib/libc-2.9.so) ==14786== by 0x40E641: cf_item_parse (conffile.c:953) ==14786== by 0x40EE5C: cf_section_parse (conffile.c:1173) ==14786== by 0x41DE96: switch_users (mainconfig.c:614) ==14786== by 0x41E6B9: read_mainconfig (mainconfig.c:874) ==14786== by 0x4257CD: main (radiusd.c:263) ==14786== ==14786== 368 (136 direct, 232 indirect) bytes in 1 blocks are definitely lost in loss record 477 of 527 ==14786== at 0x4C23224: malloc (vg_replace_malloc.c:270) ==14786== by 0x42B8AF: rad_malloc (util.c:347) ==14786== by 0x41B9BF: listen_alloc (listen.c:1735) ==14786== by 0x41BC83: proxy_new_listener (listen.c:1838) ==14786== by 0x43D514: home_server_create_callback (realms.c:2254) ==14786== by 0x4E45CFA: WalkNodeInOrder (rbtree.c:551) ==14786== by 0x4E45E78: rbtree_walk (rbtree.c:603) ==14786== by 0x43D564: home_server_create_listeners (realms.c:2280) ==14786== by 0x41CA15: listen_init (listen.c:2323) ==14786== by 0x438A36: radius_event_init (event.c:3648) ==14786== by 0x425971: main (radiusd.c:332) ==14786== ==14786== 6,800 bytes in 25 blocks are possibly lost in loss record 522 of 527 ==14786== at 0x4C252BE: calloc (vg_replace_malloc.c:593) ==14786== by 0x40104BE: _dl_allocate_tls (in /lib/ld-2.9.so) ==14786== by 0x5491C14: pthread_create (in /lib/libpthread-2.9.so) ==14786== by 0x42A611: spawn_thread (threads.c:663) ==14786== by 0x42AB1B: thread_pool_init (threads.c:862) ==14786== by 0x438803: radius_event_init (event.c:3575) ==14786== by 0x425971: main (radiusd.c:332) ==14786== ==14786== 37,440 (18,720 direct, 18,720 indirect) bytes in 60 blocks are definitely lost in loss record 526 of 527 ==14786== at 0x4C23224: malloc (vg_replace_malloc.c:270) ==14786== by 0x4E488C8: pairalloc (valuepair.c:72) ==14786== by 0x4E4AFFC: pairmake (valuepair.c:1526) ==14786== by 0x4E4B553: pairread (valuepair.c:1736) ==14786== by 0x4E4B8C4: userparse (valuepair.c:1850) ==14786== by 0x412A7F: radius_exec_program (exec.c:583) ==14786== by 0x6C1A5F5: ??? ==14786== by 0x6C1A71B: ??? ==14786== by 0x421CAB: call_modsingle (modcall.c:304) ==14786== by 0x422AD5: modcall (modcall.c:686) ==14786== by 0x41FCB8: indexed_modcall (modules.c:740) ==14786== by 0x4216FC: module_post_auth (modules.c:1662) ==14786== ==14786== 37,440 bytes in 120 blocks are definitely lost in loss record 527 of 527 ==14786== at 0x4C23224: malloc (vg_replace_malloc.c:270) ==14786== by 0x4E488C8: pairalloc (valuepair.c:72) ==14786== by 0x4E4AFFC: pairmake (valuepair.c:1526) ==14786== by 0x4E4B553: pairread (valuepair.c:1736) ==14786== by 0x4E4B8C4: userparse (valuepair.c:1850) ==14786== by 0x412A7F: radius_exec_program (exec.c:583) ==14786== by 0x6C1A5F5: ??? ==14786== by 0x421CAB: call_modsingle (modcall.c:304) ==14786== by 0x422AD5: modcall (modcall.c:686) ==14786== by 0x41FCB8: indexed_modcall (modules.c:740) ==14786== by 0x4216B4: module_pre_proxy (modules.c:1645) ==14786== by 0x435F6E: successfully_proxied_request (event.c:2230) ==14786== ==14786== LEAK SUMMARY: ==14786== definitely lost: 56,305 bytes in 183 blocks ==14786== indirectly lost: 18,952 bytes in 63 blocks ==14786== possibly lost: 6,800 bytes in 25 blocks ==14786== still reachable: 90,667 bytes in 2,548 blocks ==14786== suppressed: 0 bytes in 0 blocks ==14786== Reachable blocks (those to which a pointer was found) are not shown. ==14786== To see them, rerun with: --leak-check=full --show-reachable=yes ==14786== ==14786== For counts of detected and suppressed errors, rerun with: -v ==14786== Use --track-origins=yes to see where uninitialised values come from ==14786== ERROR SUMMARY: 715158 errors from 470 contexts (suppressed: 201 from 43)
On 06.03.2013 11:43, kao quadrantx wrote:
Hi,
I try to test with the latest version of freeradius in git 2.x.x and still get the same behavior. Seems the envp variable in radius_exec_program function (exec.c) not clean?
To help the developers to identify the bug, could you follow the documentation in doc/bugs [1] ? Also provide a freeradius -X output, and the relevant configuration part of your virtual server(s). Olivier [1] https://github.com/FreeRADIUS/freeradius-server/blob/v2.x.x/doc/bugs -- Olivier Beytrison Network & Security Engineer, HES-SO Fribourg Mail: olivier@heliosnet.org
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.
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
Sorry, update the userparse() i use is: 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
kao quadrantx wrote:
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.)
OK.
FR_TOKEN userparse(const char *buffer, VALUE_PAIR **list)
Why? Just... why? There is NO need to post code here. In case you hadn't noticed, we have access to the source. I've put a fix in for library symbols && valgrind. Please do "git pull" of v2.x.x, re-build, and re-run it under valgrind. It should show exactly where the problem is. I can then fix it. Alan DeKok.
Hi, i rebuild freeradius with the latest updated on git v2.x.x and attach the valgrind log. If you need anything else, please feel free to ask me. Thanks a lot :) On Thu, Mar 7, 2013 at 10:32 PM, Alan DeKok <aland@deployingradius.com>wrote:
kao quadrantx wrote:
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.)
OK.
FR_TOKEN userparse(const char *buffer, VALUE_PAIR **list)
Why? Just... why? There is NO need to post code here. In case you hadn't noticed, we have access to the source.
I've put a fix in for library symbols && valgrind. Please do "git pull" of v2.x.x, re-build, and re-run it under valgrind. It should show exactly where the problem is.
I can then fix it.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
new log with radiusd -m On Fri, Mar 8, 2013 at 9:35 PM, Alan DeKok <aland@deployingradius.com>wrote:
kao quadrantx wrote:
Hi,
i rebuild freeradius with the latest updated on git v2.x.x and attach the valgrind log. If you need anything else, please feel free to ask me.
Did you run with "radiusd -m" ? That is needed in order to get the debugging symbols in the modules.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
kao quadrantx wrote:
new log with radiusd -m
Which still shows ???? for many symbol names. Are you sure you're running the latest v2.x.x from git? Please try to simplify the issue down to a small configuration, and email it to me. That will let me reproduce the problem, and fix it. Alan DeKok.
participants (3)
-
Alan DeKok -
kao quadrantx -
Olivier Beytrison