Unstable freeRADIUS (authorization) work

Манцуров Дмитрий Вячеславович MantsurovDV at volgatech.net
Fri Jun 3 15:14:11 CEST 2016


I have freeRADIUS version 2.2.5 installed on Debian GNU/Linux 8.4 (Jessie).
freeRADIUS use with telephone station. Now testing with two users. Their User-Names 682808 and 686038.

When I run freeRADIUS as daemon, it works about one hour (sometimes less). Then I get for one of users: "Auth: [preprocess] No huntgroup access..." (log below). And another user can continue to work
When I run FreeRADIUS in debug mode (freeradius -X), it can work for three days, I did not check longer.

Detailed log, when user was authorize:
Fri Jun  3 14:57:46 2016 : Info:        expand: %{debug:3} -> 0
Fri Jun  3 14:57:46 2016 : Info: +++} # update control = noop
Fri Jun  3 14:57:46 2016 : Info: ++} # if ("%{User-Name}" == "682808") = noop
Fri Jun  3 14:57:46 2016 : Info:   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 1434
Fri Jun  3 14:57:46 2016 : Info:   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 1434
Fri Jun  3 14:57:46 2016 : Info: ++[preprocess] = ok
Fri Jun  3 14:57:46 2016 : Info:   modsingle[authorize]: calling auth_log (rlm_detail) for request 1434
Fri Jun  3 14:57:46 2016 : Info: [auth_log]     expand: %{Packet-Src-IP-Address} -> 10.10.10.200
Fri Jun  3 14:57:46 2016 : Info: [auth_log]     expand: /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d -> /var/log/freeradius/radacc$
Fri Jun  3 14:57:46 2016 : Info: [auth_log] /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/10$
Fri Jun  3 14:57:46 2016 : Info: [auth_log]     expand: %t -> Fri Jun  3 14:57:46 2016
Fri Jun  3 14:57:46 2016 : Info:   modsingle[authorize]: returned from auth_log (rlm_detail) for request 1434
Fri Jun  3 14:57:46 2016 : Info: ++[auth_log] = ok
Fri Jun  3 14:57:46 2016 : Info:   modsingle[authorize]: calling files (rlm_files) for request 1434
Fri Jun  3 14:57:46 2016 : Info: [files] users: Matched entry DEFAULT at line 62
Fri Jun  3 14:57:46 2016 : Info: [files] users: Matched entry DEFAULT at line 65
Fri Jun  3 14:57:46 2016 : Info:   modsingle[authorize]: returned from files (rlm_files) for request 1434
Fri Jun  3 14:57:46 2016 : Info: ++[files] = ok
Fri Jun  3 14:57:46 2016 : Info:   modsingle[authorize]: calling monthlycounter (rlm_counter) for request 1434
Fri Jun  3 14:57:46 2016 : Info:   modsingle[authorize]: returned from monthlycounter (rlm_counter) for request 1434
Fri Jun  3 14:57:46 2016 : Info: ++[monthlycounter] = ok
Fri Jun  3 14:57:46 2016 : Info:   modsingle[authorize]: calling expiration (rlm_expiration) for request 1434
Fri Jun  3 14:57:46 2016 : Info:   modsingle[authorize]: returned from expiration (rlm_expiration) for request 1434
Fri Jun  3 14:57:46 2016 : Info: ++[expiration] = noop
Fri Jun  3 14:57:46 2016 : Info:   modsingle[authorize]: calling logintime (rlm_logintime) for request 1434
Fri Jun  3 14:57:46 2016 : Info:   modsingle[authorize]: returned from logintime (rlm_logintime) for request 1434
Fri Jun  3 14:57:46 2016 : Info: ++[logintime] = noop
Fri Jun  3 14:57:46 2016 : Info: +} # group authorize = ok
Fri Jun  3 14:57:46 2016 : Info: Found Auth-Type = Accept
Fri Jun  3 14:57:46 2016 : Info: Auth-Type = Accept, accepting the user
Fri Jun  3 14:57:46 2016 : Auth: Login OK: [682808/<via Auth-Type = Accept>] (from client localhost port 0 cli 682808)
Fri Jun  3 14:57:46 2016 : Info:   WARNING: Empty post-auth section.  Using default return values.
Fri Jun  3 14:57:46 2016 : Info: Sending Access-Accept packet to host 10.10.10.200 port 49777, id=15, length=0
Fri Jun  3 14:57:46 2016 : Info:        Auth-Type := Reject
Fri Jun  3 14:57:46 2016 : Info:        h323-credit-time = "h323-credit-time=900"
Fri Jun  3 14:57:46 2016 : Info:        Session-Timeout = 5977
Fri Jun  3 14:57:46 2016 : Info: Finished request 1434.
Fri Jun  3 14:57:48 2016 : Info: Cleaning up request 1434 ID 15 with timestamp +2483

Not authorize:
Fri Jun  3 15:18:27 2016 : Info:        expand: %{debug:3} -> 0
Fri Jun  3 15:18:27 2016 : Info: +++} # update control = noop
Fri Jun  3 15:18:27 2016 : Info: ++} # if ("%{User-Name}" == "682808") = noop
Fri Jun  3 15:18:27 2016 : Info:   modsingle[authorize]: calling preprocess (rlm_preprocess) for request 2273
Fri Jun  3 15:18:27 2016 : Auth: [preprocess] No huntgroup access: [682808] (from client localhost port 0 cli 682808)
Fri Jun  3 15:18:27 2016 : Info:   modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 2273
Fri Jun  3 15:18:27 2016 : Info: ++[preprocess] = reject
Fri Jun  3 15:18:27 2016 : Info: +} # group authorize = reject
Fri Jun  3 15:18:27 2016 : Auth: Invalid user: [682808/<no User-Password attribute>] (from client localhost port 0 cli 682808)
Fri Jun  3 15:18:27 2016 : Info: Using Post-Auth-Type REJECT
Fri Jun  3 15:18:27 2016 : Info:   WARNING: Unknown value specified for Post-Auth-Type.  Cannot perform requested action.
Fri Jun  3 15:18:27 2016 : Info: Delaying reject of request 2273 for 1 seconds
Fri Jun  3 15:18:28 2016 : Info: Sending delayed reject for request 2273
Fri Jun  3 15:18:28 2016 : Info: Sending Access-Reject packet to host 10.10.10.200 port 46827, id=42, length=0
Fri Jun  3 15:18:30 2016 : Info: Cleaning up request 2273 ID 42 with timestamp +3724

I would be grateful for any ideas.



More information about the Freeradius-Users mailing list