Hi, got a gdb bt below. This time for another request, which took a different path in the config, crash happened after linelog this time. So I think that whatever SEGVs here is not directly related to your fix to suppress... As per your reminder yesterday, I'll open a ticket for this. (0) # Executing section post-auth from file /usr/local/freeradius/config/raddb/sites-enabled/staff (0) post-auth { (0) restena_log_policy restena_log_policy { (0) reply_log : expand: "/var/log/radius/radacct/%Y%m%d/%{RESTENA-Service-Type}-service/reply-detail" -> '/var/log/radius/radacct/20140108/Staff-AAI-service/reply-detail' (0) reply_log : /var/log/radius/radacct/%Y%m%d/%{RESTENA-Service-Type}-service/reply-detail expands to /var/log/radius/radacct/20140108/Staff-AAI-service/reply-detail (0) reply_log : expand: "%t" -> 'Wed Jan 8 08:19:21 2014' (0) [reply_log] = ok (0) linelog : expand: "%{%{Acct-Status-Type}:-%{%{reply:Packet-Type}:-format}}" -> 'Access-Accept' (0) linelog : expand: "/var/log/radius/activity.log" -> '/var/log/radius/activity.log' (0) linelog : expand: "[%S] [AUTH OK ] '%{User-Name}' (%{RESTENA-Service-Type}:%{client:shortname})" -> '[2014-01-08 08:19:21] [AUTH OK ] 'swinter' (Staff-AAI:restmir-dns-lu-v4)' (0) [linelog] = ok Program received signal SIGSEGV, Segmentation fault. 0x00007ffff4415e47 in mod_post_auth (instance=0x9854e0, request=0x9d8410) at <command-line>:1452 1452 <command-line>: No such file or directory. (gdb) bt #0 0x00007ffff4415e47 in mod_post_auth (instance=0x9854e0, request=0x9d8410) at <command-line>:1452 #1 0x000000000041ecde in call_modsingle (sp=<optimized out>, request=0x9d8410, component=RLM_COMPONENT_POST_AUTH) at <command-line>:310 #2 modcall_recurse (request=request@entry=0x9d8410, component=component@entry=RLM_COMPONENT_POST_AUTH, depth=depth@entry=2, entry=entry@entry=0x7fffffffdc40) at <command-line>:576 #3 0x000000000041e2f2 in modcall_child (request=0x9d8410, component=RLM_COMPONENT_POST_AUTH, depth=2, entry=0x7fffffffdc28, c=0x9b7730, result=0x7fffffffd2bc) at <command-line>:413 #4 0x000000000041e4c4 in modcall_recurse (request=request@entry=0x9d8410, component=component@entry=RLM_COMPONENT_POST_AUTH, depth=depth@entry=1, entry=entry@entry=0x7fffffffdc28) at <command-line>:779 #5 0x000000000041e2f2 in modcall_child (request=0x9d8410, component=RLM_COMPONENT_POST_AUTH, depth=1, entry=0x7fffffffdc10, c=0x9b76b0, result=0x7fffffffd7bc) at <command-line>:413 #6 0x000000000041e4c4 in modcall_recurse (request=request@entry=0x9d8410, component=component@entry=RLM_COMPONENT_POST_AUTH, depth=depth@entry=0, entry=entry@entry=0x7fffffffdc10) at <command-line>:779 #7 0x000000000041f78d in modcall (component=component@entry=RLM_COMPONENT_POST_AUTH, c=c@entry=0x9b7900, request=request@entry=0x9d8410) at <command-line>:1035 #8 0x000000000041d249 in indexed_modcall (comp=comp@entry=RLM_COMPONENT_POST_AUTH, idx=idx@entry=0, request=request@entry=0x9d8410) at <command-line>:746 #9 0x000000000041dd5f in process_post_auth (postauth_type=postauth_type@entry=0, request=request@entry=0x9d8410) at <command-line>:1726 #10 0x000000000040ee84 in rad_postauth (request=request@entry=0x9d8410) at <command-line>:300 #11 0x000000000042b6cc in request_finish (action=<optimized out>, request=0x9d8410) at <command-line>:1137 #12 request_running (request=0x9d8410, action=<optimized out>) at <command-line>:1261 #13 0x000000000042c153 in request_virtual_server (request=0x9d8410, action=<optimized out>) at <command-line>:2160 #14 0x000000000042979e in request_queue_or_run (request=request@entry=0x9d8410, process=process@entry=0x42c0c0 <request_virtual_server>) at <command-line>:850 #15 0x0000000000429895 in request_proxy (request=request@entry=0x9d8410, retransmit=retransmit@entry=0) at <command-line>:2439 #16 0x000000000042bde0 in request_running (request=request@entry=0x9d8410, action=action@entry=1) at <command-line>:1243 #17 0x000000000042979e in request_queue_or_run (request=0x9d8410, process=process@entry=0x42b300 <request_running>) at <command-line>:850 #18 0x0000000000429c74 in request_receive (listener=listener@entry=0x9d6fe0, packet=0x9d8270, client=client@entry=0x8ff5a0, fun=fun@entry=0x40eed0 <rad_authenticate>) at <command-line>:1429 #19 0x000000000041900c in auth_socket_recv (listener=0x9d6fe0) at <command-line>:1522 #20 0x0000000000426fef in event_socket_handler (xel=<optimized out>, fd=<optimized out>, ctx=0x9d6fe0) at <command-line>:3514 #21 0x00007ffff79acecc in fr_event_loop (el=0x9c0da0) at <command-line>:416 #22 0x000000000042c7a1 in radius_event_process () at <command-line>:4231 #23 0x000000000040e515 in main (argc=<optimized out>, argv=<optimized out>) at <command-line>:478 (gdb) Stefan On 07.01.2014 12:52, Arran Cudbard-Bell wrote:
On 7 Jan 2014, at 11:16, Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
On 7 Jan 2014, at 07:51, Stefan Winter <stefan.winter@restena.lu> wrote:
Hi,
And the log files do contain the User-Password attribute.
That shouldn't happen
Fixed.
Umm. In a way, yes. With current SVN (v3.0.x from a few minutes ago), the logs don't contain the User-Password.
Unfortunately, shortly after detail is done (it logs the packet, omits the User-Password), the server crashes with a SEGV.
Here's the -X log of the moment:
(0) auth_log_silent : /var/log/radius/radacct/%Y%m%d/%{RESTENA-Service-Type}-service/auth-detail expands to /var/log/radius/radacct/20140107/Staff-IMAP-service/auth-detail (0) auth_log_silent : expand: "%t" -> 'Tue Jan 7 08:43:27 2014' (0) [auth_log_silent] = ok (0) ? if ( "%{RESTENA-Service-Type}" == "Staff-IMAP" && "%{strlen:%{User-Password}}" == "96" ) (0) expand: "Staff-IMAP" -> 'Staff-IMAP' (0) expand: "%{RESTENA-Service-Type}" -> 'Staff-IMAP' (0) expand: "96" -> '96' (0) expand: "%{strlen:%{User-Password}}" -> '96' (0) ? if ( "%{RESTENA-Service-Type}" == "Staff-IMAP" && "%{strlen:%{User-Password}}" == "96" ) -> TRUE (0) if ( "%{RESTENA-Service-Type}" == "Staff-IMAP" && "%{strlen:%{User-Password}}" == "96" ) { Segmentation fault
My config for this states:
auth_log_silent if ( "%{RESTENA-Service-Type}" == "Staff-IMAP" && "%{strlen:%{User-Password}}" == "96" ) { sql-webmailsso }
So it crashed before invoking an sql instance? The same worked on 3.0.0.
Yes that doesn't exactly mean much it being C.
I can't reproduce it by calling strlen, could you maybe provide a backtrace?
(1) # Executing section authorize from file /usr/local/freeradius/etc/raddb/sites-enabled/default (1) authorize { (1) detail : expand: "/usr/local/freeradius/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d" -> '/usr/local/freeradius/var/log/radius/radacct/127.0.0.1/detail-20140107' (1) detail : /usr/local/freeradius/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /usr/local/freeradius/var/log/radius/radacct/127.0.0.1/detail-20140107 (1) detail : expand: "%t" -> 'Tue Jan 7 11:14:32 2014' (1) [detail] = ok (1) update control { (1) expand: "%{strlen:%{User-Password}}" -> '3' (1) Tmp-Integer-0 := 3 (1) } # update control = noop (1) ? if ("%{strlen:%{User-Password}}" == "3") (1) expand: "3" -> '3' (1) expand: "%{strlen:%{User-Password}}" -> '3' (1) ? if ("%{strlen:%{User-Password}}" == "3") -> TRUE (1) if ("%{strlen:%{User-Password}}" == "3") { (1) [reject] = reject (1) } # if ("%{strlen:%{User-Password}}" == "3") = reject (1) } # authorize = reject (1) Using Post-Auth-Type Reject
(1) # Executing section authorize from file /usr/local/freeradius/etc/raddb/sites-enabled/default (1) authorize { (1) detail : expand: "/usr/local/freeradius/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d" -> '/usr/local/freeradius/var/log/radius/radacct/127.0.0.1/detail-20140107' (1) detail : /usr/local/freeradius/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /usr/local/freeradius/var/log/radius/radacct/127.0.0.1/detail-20140107 (1) detail : expand: "%t" -> 'Tue Jan 7 11:51:32 2014' (1) [detail] = ok (1) update control { (1) expand: "%{strlen:%{User-Password}}" -> '3' (1) Tmp-Integer-0 := 3 (1) } # update control = noop (1) ? if ("%{strlen:%{User-Password}}" == "3") (1) expand: "3" -> '3' (1) expand: "%{strlen:%{User-Password}}" -> '3' (1) ? if ("%{strlen:%{User-Password}}" == "3") -> TRUE (1) if ("%{strlen:%{User-Password}}" == "3") { (1) sql : expand: "%{User-Name}" -> 'foo' (1) sql : SQL-User-Name set to 'foo' rlm_sql (sql): Reserved connection (4) (1) sql : expand: "SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id" -> 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'foo' ORDER BY id' rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'foo' ORDER BY id' (1) sql : expand: "SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority" -> 'SELECT groupname FROM radusergroup WHERE username = 'foo' ORDER BY priority' rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE username = 'foo' ORDER BY priority' rlm_sql (sql): Released connection (4) rlm_sql (sql): Closing connection (1): Too many free connections (4 > 3) rlm_sql_sqlite: Socket destructor called, closing socket (1) [sql] = notfound
Still can't reproduce it...
Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team
FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
-- Stefan WINTER Ingenieur de Recherche Fondation RESTENA - Réseau Téléinformatique de l'Education Nationale et de la Recherche 6, rue Richard Coudenhove-Kalergi L-1359 Luxembourg Tel: +352 424409 1 Fax: +352 422473 PGP key updated to 4096 Bit RSA - I will encrypt all mails if the recipient's key is known to me http://pgp.mit.edu:11371/pks/lookup?op=get&search=0xC0DE6A358A39DC66