Proxy (check status of the 3rd party server)
Hi Could you please tell me, why my RADIUS server doesnt find reply (status-check via using "request" ) from 3rd party RADIUS server ? The PCAP file (contains correct response for Accounting Requests from 3rd party RADIUS server) is in the attachment. Thank you very much. Proxy configuration for the 3rd party RADIUS server: ... WARNING: Ignoring "response_window = 30.000000", forcing to "response_window = 5.000000" home_server ssed_server3_prod { ipaddr = 10.14.135.19 port = 1812 type = "auth+acct" secret = <<< secret >>> response_window = 30.000000 response_timeouts = 1 max_outstanding = 65536 zombie_period = 40 status_check = "request" ping_interval = 30 check_interval = 6 check_timeout = 4 num_answers_to_alive = 3 revive_interval = 300 username = "orange-system" password = "incorrect" limit { max_connections = 16 max_requests = 0 lifetime = 0 idle_timeout = 0 } coa { irt = 2 mrt = 16 mrc = 5 mrd = 30 } } ... Radius log: Tue Aug 11 08:56:31 2015 : Proxy: No outstanding request was found for reply from host 10.14.135.19 port 1813 - ID 66 Tue Aug 11 08:56:35 2015 : Error: No response to status check 2041440 for home server 10.14.135.19 port 1813 Tue Aug 11 08:56:39 2015 : Proxy: No outstanding request was found for reply from host 10.14.135.19 port 1813 - ID 43 Tue Aug 11 08:56:43 2015 : Error: No response to status check 2041671 for home server 10.14.135.19 port 1813 Tue Aug 11 08:56:43 2015 : Proxy: No outstanding request was found for reply from host 10.14.135.19 port 1813 - ID 208 Tue Aug 11 08:56:47 2015 : Error: No response to status check 2041801 for home server 10.14.135.19 port 1813 Tue Aug 11 08:56:49 2015 : Proxy: No outstanding request was found for reply from host 10.14.135.19 port 1813 - ID 247 Tue Aug 11 08:56:53 2015 : Error: No response to status check 2041965 for home server 10.14.135.19 port 1813 Tue Aug 11 08:56:54 2015 : Proxy: No outstanding request was found for reply from host 10.14.135.19 port 1813 - ID 223 Tue Aug 11 08:56:58 2015 : Error: No response to status check 2042114 for home server 10.14.135.19 port 1813 Tue Aug 11 08:56:58 2015 : Proxy: No outstanding request was found for reply from host 10.14.135.19 port 1813 - ID 100 Tue Aug 11 08:57:02 2015 : Error: No response to status check 2042235 for home server 10.14.135.19 port 1813 Tue Aug 11 08:57:06 2015 : Proxy: No outstanding request was found for reply from host 10.14.135.19 port 1813 - ID 206 Tue Aug 11 08:57:10 2015 : Error: No response to status check 2042456 for home server 10.14.135.19 port 1813 Tue Aug 11 08:57:14 2015 : Proxy: No outstanding request was found for reply from host 10.14.135.19 port 1813 - ID 128 Tue Aug 11 08:57:18 2015 : Error: No response to status check 2042679 for home server 10.14.135.19 port 1813 Tue Aug 11 08:57:18 2015 : Proxy: No outstanding request was found for reply from host 10.14.135.19 port 1813 - ID 94 Tue Aug 11 08:57:22 2015 : Error: No response to status check 2042816 for home server 10.14.135.19 port 1813 Tue Aug 11 08:57:25 2015 : Proxy: No outstanding request was found for reply from host 10.14.135.19 port 1813 - ID 96 Tue Aug 11 08:57:29 2015 : Error: No response to status check 2042996 for home server 10.14.135.19 port 1813 Tue Aug 11 08:57:30 2015 : Proxy: No outstanding request was found for reply from host 10.14.135.19 port 1813 - ID 30 Tue Aug 11 08:57:34 2015 : Error: No response to status check 2043142 for home server 10.14.135.19 port 1813 Tue Aug 11 08:57:35 2015 : Proxy: No outstanding request was found for reply from host 10.14.135.19 port 1813 - ID 150 Tue Aug 11 08:57:39 2015 : Error: No response to status check 2043279 for home server 10.14.135.19 port 1813 Tue Aug 11 08:57:40 2015 : Proxy: No outstanding request was found for reply from host 10.14.135.19 port 1813 - ID 172
On Aug 11, 2015, at 9:14 AM, Peter Balsianok <balsianok.peter@gmail.com> wrote:
Could you please tell me, why my RADIUS server doesnt find reply (status-check via using "request" ) from 3rd party RADIUS server ?
Post the debug output as suggested in the FAQ, "man" pages, web pages, and daily on this list. Alan DeKok.
Well, its very difficult, we have more then 50 req/s. Its hard to track this issue. As you can see in the attached PCAP, response comes from 3rd party server for each request Maybe it will help Tue Aug 11 11:02:14 2015 : Debug: (2269289) Not sending reply to client. Tue Aug 11 11:02:14 2015 : Debug: (2269289) Finished request Tue Aug 11 11:02:14 2015 : Debug: Thread 51 waiting to be assigned a request Tue Aug 11 11:02:14 2015 : Debug: (2269290) proxy: Trying to allocate ID (0/2) Tue Aug 11 11:02:14 2015 : Debug: (2269290) proxy: request is now in proxy hash Tue Aug 11 11:02:14 2015 : Debug: (2269290) proxy: allocating destination 10.14.135.18 port 1813 - Id 145 Tue Aug 11 11:02:14 2015 : Debug: PING: Waiting 4 seconds for response to ping Tue Aug 11 11:02:14 2015 : Debug: PING: Next status packet in 6 seconds Tue Aug 11 11:02:14 2015 : Debug: (2269278) <done>: Cleaning up request packet ID 228 with timestamp +77872 Tue Aug 11 11:02:14 2015 : Proxy: No outstanding request was found for reply from host 10.14.135.18 port 1813 - ID 145 Tue Aug 11 11:02:14 2015 : Debug: Thread 54 got semaphore Tue Aug 11 11:02:14 2015 : Debug: Thread 54 handling request 2269291, (3792 handled so far) Tue Aug 11 11:02:14 2015 : Debug: (2269291) Received Accounting-Request Id 236 from 213.151.237.224:1812 to 10.14.131.103:1813 length 749 ... Tue Aug 11 11:02:18 2015 : Debug: (2269410) Finished request Tue Aug 11 11:02:18 2015 : Debug: Thread 51 waiting to be assigned a request Tue Aug 11 11:02:18 2015 : Debug: (2269402) <done>: Cleaning up request packet ID 119 with timestamp +77876 Tue Aug 11 11:02:18 2015 : Error: No response to status check 2269290 for home server 10.14.135.18 port 1813 Tue Aug 11 11:02:18 2015 : Debug: (2269290) proxy: request is no longer in proxy hash Tue Aug 11 11:02:18 2015 : Debug: Thread 48 got semaphore Tue Aug 11 11:02:18 2015 : Debug: Thread 48 handling request 2269411, (14568 handled so far) Tue Aug 11 11:02:18 2015 : Debug: (2269411) Received Accounting-Request Id 48 from 85.237.224.1:1646 to 10.14.131.103:1646 length 235 ... On Tue, Aug 11, 2015 at 9:42 AM, Alan DeKok <aland@deployingradius.com> wrote:
On Aug 11, 2015, at 9:14 AM, Peter Balsianok <balsianok.peter@gmail.com> wrote:
Could you please tell me, why my RADIUS server doesnt find reply (status-check via using "request" ) from 3rd party RADIUS server ?
Post the debug output as suggested in the FAQ, "man" pages, web pages, and daily on this list.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Please try the v3.0.x branch from git. I've put some more debugging messages in for Status-Server packets. My guess is you're using FreeBSD. It's networking is a bit different than Linux, so some of the assumptions in the code were wrong. I've put in fixes which are better for matching replies to requests. Alan DeKok.
Thank very much for help. We are using Redhat & Debian. The test was done on the Redhat Here is debug output: Fri Aug 14 13:23:20 2015 : Debug: (3) proxy: Trying to allocate ID (0/2) Fri Aug 14 13:23:20 2015 : Debug: (3) proxy: request is now in proxy hash Fri Aug 14 13:23:20 2015 : Debug: (3) proxy: allocating destination 127.0.0.1 port 61813 - Id 198 Fri Aug 14 13:23:20 2015 : Debug: PING: Waiting 4 seconds for response to ping 01 0f 6f 72 61 6e 67 65 2d 73 79 73 74 65 6d 28 06 00 00 00 02 2c 0a 30 30 30 30 30 30 30 30 37 06 55 cd cf a8 20 20 53 74 61 74 75 73 20 43 68 65 63 6b 20 32 2e 20 41 72 65 20 79 6f 75 20 61 6c 69 76 65 3f Code: 4 Id: 198 Length: 89 Vector: daa7f1987b6f95c70b87dbdfa2d12a2a Data: 01 0f 6f 72 61 6e 67 65 2d 73 79 73 74 65 6d 28 06 00 00 00 02 2c 0a 30 30 30 30 30 30 30 30 37 06 55 cd cf a8 20 20 53 74 61 74 75 73 20 43 68 65 63 6b 20 32 2e 20 41 72 65 20 79 6f 75 20 61 6c 69 76 65 3f Fri Aug 14 13:23:20 2015 : Debug: PING: Next status packet in 6 seconds Fri Aug 14 13:23:20 2015 : Debug: Waking up in 3.9 seconds. Code: 5 Id: 198 Length: 20 Vector: 4c86d4e105670d850481902077ab2fe1 Fri Aug 14 13:23:20 2015 : Proxy: No outstanding request was found for reply from host 127.0.0.1 port 61813 - ID 198 Fri Aug 14 13:23:20 2015 : Debug: Waking up in 3.9 seconds. On Fri, Aug 14, 2015 at 11:17 AM, Alan DeKok <aland@deployingradius.com> wrote:
Please try the v3.0.x branch from git. I've put some more debugging messages in for Status-Server packets.
My guess is you're using FreeBSD. It's networking is a bit different than Linux, so some of the assumptions in the code were wrong. I've put in fixes which are better for matching replies to requests.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On Aug 14, 2015, at 1:24 PM, Peter Balsianok <balsianok.peter@gmail.com> wrote:
Thank very much for help.
We are using Redhat & Debian. The test was done on the Redhat
Here is debug output:
Please try the v3.0.x branch from git. As I said, I put fixes in which should help, and which also improve the debug messages. Alan DeKok.
Sorry, i have downloaded v3.0.x branch, but didnt install correctly Fri Aug 14 14:22:15 2015 : Debug: (4) proxy: Trying to allocate ID (0/2) Fri Aug 14 14:22:15 2015 : Debug: (4) proxy: request is now in proxy hash Fri Aug 14 14:22:15 2015 : Debug: (4) proxy: allocating destination 127.0.0.1 port 61813 - Id 206 Fri Aug 14 14:22:15 2015 : Debug: PING: Waiting 4 seconds for response to ping Fri Aug 14 14:22:15 2015 : Debug: (4) Sent Accounting-Request Id 206 from 0.0.0.0:48830 to 127.0.0.1:61813 length 0 Fri Aug 14 14:22:15 2015 : Debug: (4) User-Name := "orange-system" Fri Aug 14 14:22:15 2015 : Debug: (4) Acct-Status-Type := Stop Fri Aug 14 14:22:15 2015 : Debug: (4) Acct-Session-Id := "00000000" Fri Aug 14 14:22:15 2015 : Debug: (4) Event-Timestamp := "Aug 14 2015 14:22:15 CEST" Fri Aug 14 14:22:15 2015 : Debug: (4) NAS-Identifier := "Status Check 3. Are you alive?" 01 0f 6f 72 61 6e 67 65 2d 73 79 73 74 65 6d 28 06 00 00 00 02 2c 0a 30 30 30 30 30 30 30 30 37 06 55 cd dd 77 20 20 53 74 61 74 75 73 20 43 68 65 63 6b 20 33 2e 20 41 72 65 20 79 6f 75 20 61 6c 69 76 65 3f Code: 4 Id: 206 Length: 89 Vector: c000e645560391192cbdf8eecd577b1f Data: 01 0f 6f 72 61 6e 67 65 2d 73 79 73 74 65 6d 28 06 00 00 00 02 2c 0a 30 30 30 30 30 30 30 30 37 06 55 cd dd 77 20 20 53 74 61 74 75 73 20 43 68 65 63 6b 20 33 2e 20 41 72 65 20 79 6f 75 20 61 6c 69 76 65 3f Fri Aug 14 14:22:15 2015 : Debug: PING: Next status packet in 6 seconds Fri Aug 14 14:22:15 2015 : Debug: Waking up in 3.9 seconds. Code: 5 Id: 206 Length: 20 Vector: 49408343fb018a018c76d2046558b218 Fri Aug 14 14:22:15 2015 : Proxy: No outstanding request was found for Accounting-Response packet from host 127.0.0.1 port 61813 - ID 206 On Fri, Aug 14, 2015 at 2:03 PM, Alan DeKok <aland@deployingradius.com> wrote:
On Aug 14, 2015, at 1:24 PM, Peter Balsianok <balsianok.peter@gmail.com> wrote:
Thank very much for help.
We are using Redhat & Debian. The test was done on the Redhat
Here is debug output:
Please try the v3.0.x branch from git. As I said, I put fixes in which should help, and which also improve the debug messages.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On 14 Aug 2015, at 08:23, Peter Balsianok <balsianok.peter@gmail.com> wrote:
Sorry, i have downloaded v3.0.x branch, but didnt install correctly
And the error was.... Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS development team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On the server were running two radius instances (production one). Therefore i had to stop them before run make install On Fri, Aug 14, 2015 at 2:45 PM, Arran Cudbard-Bell < a.cudbardb@freeradius.org> wrote:
On 14 Aug 2015, at 08:23, Peter Balsianok <balsianok.peter@gmail.com> wrote:
Sorry, i have downloaded v3.0.x branch, but didnt install correctly
And the error was....
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
On Aug 14, 2015, at 2:23 PM, Peter Balsianok <balsianok.peter@gmail.com> wrote: Hmm... what kind of system are you running? i.e. is this a container? A plain OS? What is unusual about this? Can you try using Status-Server packets for the checks, instead of Accounting-Request packets? Alan DeKok.
[radiusd@tdrad1 acct-test]$ cat /etc/redhat-release Red Hat Enterprise Linux Server release 5.11 (Tikanga) A virtual machine on the ESX server Status-Server -> Yes i can try On Fri, Aug 14, 2015 at 3:18 PM, Alan DeKok <aland@deployingradius.com> wrote:
On Aug 14, 2015, at 2:23 PM, Peter Balsianok <balsianok.peter@gmail.com> wrote:
Hmm... what kind of system are you running? i.e. is this a container? A plain OS? What is unusual about this?
Can you try using Status-Server packets for the checks, instead of Accounting-Request packets?
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Debug output (accounting server): Fri Aug 14 15:33:24 2015 : Debug: (2) proxy: Trying to allocate ID (0/2) Fri Aug 14 15:33:24 2015 : Debug: (2) proxy: request is now in proxy hash Fri Aug 14 15:33:24 2015 : Debug: (2) proxy: allocating destination 127.0.0.1 port 61813 - Id 65 Fri Aug 14 15:33:24 2015 : Debug: PING: Waiting 4 seconds for response to ping Fri Aug 14 15:33:24 2015 : Debug: (2) Sent Status-Server Id 65 from 0.0.0.0:39764 to 127.0.0.1:61813 length 0 Fri Aug 14 15:33:24 2015 : Debug: (2) Message-Authenticator := 0x00 Fri Aug 14 15:33:24 2015 : Debug: (2) NAS-Identifier := "Status Check 1. Are you alive?" 50 12 ... 20 20 53 74 61 74 75 73 20 43 68 65 63 6b 20 31 2e 20 41 72 65 20 79 6f 75 20 61 6c 69 76 65 3f Code: 12 Id: 65 Length: 70 Vector: 70a010641803b9f6c5019325204e8bd3 Data: 50 12 20 f5 e8 9b 36 55 22 13 c4 f9 6e 71 f4 39 cf ea 20 20 53 74 61 74 75 73 20 43 68 65 63 6b 20 31 2e 20 41 72 65 20 79 6f 75 20 61 6c 69 76 65 3f Fri Aug 14 15:33:24 2015 : Debug: PING: Next status packet in 6 seconds Fri Aug 14 15:33:24 2015 : Debug: Waking up in 3.9 seconds. Code: 5 Id: 65 Length: 20 Vector: 0b2dc4a4cb1eef4b89f64dbdd20744ed Fri Aug 14 15:33:24 2015 : Proxy: No outstanding request was found for Accounting-Response packet from host 127.0.0.1 port 61813 - ID 65 Debug output (3rd party server): Listening on acct address 127.0.0.1 port 61813 bound to server default Ready to process requests (0) Received Status-Server Id 65 from 127.0.0.1:39764 to 127.0.0.1:61813 length 70 (0) Message-Authenticator = 0x20f5e89b36552213c4f96e71f439cfea (0) NAS-Identifier = "Status Check 1. Are you alive?" (0) Sent Accounting-Response Id 65 from 127.0.0.1:61813 to 127.0.0.1:39764 length 0 (0) Finished request Waking up in 1.9 seconds. (0) <done>: Cleaning up request packet ID 65 with timestamp +4 Ready to process requests (1) Received Status-Server Id 21 from 127.0.0.1:39764 to 127.0.0.1:61813 length 70 (1) Message-Authenticator = 0x557c9db0ae54d9e837a06151a5f7d951 (1) NAS-Identifier = "Status Check 2. Are you alive?" (1) Sent Accounting-Response Id 21 from 127.0.0.1:61813 to 127.0.0.1:39764 length 0 (1) Finished request Waking up in 1.9 seconds. On Fri, Aug 14, 2015 at 3:30 PM, Peter Balsianok <balsianok.peter@gmail.com> wrote:
[radiusd@tdrad1 acct-test]$ cat /etc/redhat-release Red Hat Enterprise Linux Server release 5.11 (Tikanga)
A virtual machine on the ESX server
Status-Server -> Yes i can try
On Fri, Aug 14, 2015 at 3:18 PM, Alan DeKok <aland@deployingradius.com> wrote:
On Aug 14, 2015, at 2:23 PM, Peter Balsianok <balsianok.peter@gmail.com> wrote:
Hmm... what kind of system are you running? i.e. is this a container? A plain OS? What is unusual about this?
Can you try using Status-Server packets for the checks, instead of Accounting-Request packets?
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Fri Aug 14 16:31:17 2015 : Debug: (2) proxy: Trying to allocate ID (0/2) Fri Aug 14 16:31:17 2015 : Debug: (2) proxy: request is now in proxy hash Fri Aug 14 16:31:17 2015 : Debug: (2) proxy: allocating destination 127.0.0.1 port 61813 - Id 215 Fri Aug 14 16:31:17 2015 : Debug: PING: Waiting 4 seconds for response to ping Fri Aug 14 16:31:17 2015 : Debug: (2) Sent Status-Server Id 215 from 0.0.0.0:37576 to 127.0.0.1:61813 length 0 Fri Aug 14 16:31:17 2015 : Debug: (2) Message-Authenticator := 0x00 Fri Aug 14 16:31:17 2015 : Debug: (2) NAS-Identifier := "Status Check 1. Are you alive?" 50 12 ... 20 20 53 74 61 74 75 73 20 43 68 65 63 6b 20 31 2e 20 41 72 65 20 79 6f 75 20 61 6c 69 76 65 3f Socket: 13 Proto: 0 Src IP: 0.0.0.0 port: 37576 Dst IP: 127.0.0.1 port: 61813 Code: 12 Id: 215 Length: 70 Vector: 56dd3fb2660db32c59405402f78de7d4 Data: 50 12 f4 df 14 78 db d0 45 66 0b 15 4f 71 88 de 47 06 20 20 53 74 61 74 75 73 20 43 68 65 63 6b 20 31 2e 20 41 72 65 20 79 6f 75 20 61 6c 69 76 65 3f Fri Aug 14 16:31:17 2015 : Debug: PING: Next status packet in 6 seconds Fri Aug 14 16:31:17 2015 : Debug: Waking up in 3.9 seconds. Socket: 13 Proto: 0 Src IP: 127.0.0.1 port: 61813 Dst IP: 127.0.0.1 port: 37576 Code: 5 Id: 215 Length: 20 Vector: cd395b6837e57b2ed82175fffbe94dba Fri Aug 14 16:31:17 2015 : Proxy: No outstanding request was found for Accounting-Response packet from host 127.0.0.1 port 61813 - ID 215 On Fri, Aug 14, 2015 at 3:35 PM, Peter Balsianok <balsianok.peter@gmail.com> wrote:
Debug output (accounting server): Fri Aug 14 15:33:24 2015 : Debug: (2) proxy: Trying to allocate ID (0/2) Fri Aug 14 15:33:24 2015 : Debug: (2) proxy: request is now in proxy hash Fri Aug 14 15:33:24 2015 : Debug: (2) proxy: allocating destination 127.0.0.1 port 61813 - Id 65 Fri Aug 14 15:33:24 2015 : Debug: PING: Waiting 4 seconds for response to ping Fri Aug 14 15:33:24 2015 : Debug: (2) Sent Status-Server Id 65 from 0.0.0.0:39764 to 127.0.0.1:61813 length 0 Fri Aug 14 15:33:24 2015 : Debug: (2) Message-Authenticator := 0x00 Fri Aug 14 15:33:24 2015 : Debug: (2) NAS-Identifier := "Status Check 1. Are you alive?" 50 12 ... 20 20 53 74 61 74 75 73 20 43 68 65 63 6b 20 31 2e 20 41 72 65 20 79 6f 75 20 61 6c 69 76 65 3f Code: 12 Id: 65 Length: 70 Vector: 70a010641803b9f6c5019325204e8bd3 Data: 50 12 20 f5 e8 9b 36 55 22 13 c4 f9 6e 71 f4 39 cf ea 20 20 53 74 61 74 75 73 20 43 68 65 63 6b 20 31 2e 20 41 72 65 20 79 6f 75 20 61 6c 69 76 65 3f Fri Aug 14 15:33:24 2015 : Debug: PING: Next status packet in 6 seconds Fri Aug 14 15:33:24 2015 : Debug: Waking up in 3.9 seconds. Code: 5 Id: 65 Length: 20 Vector: 0b2dc4a4cb1eef4b89f64dbdd20744ed Fri Aug 14 15:33:24 2015 : Proxy: No outstanding request was found for Accounting-Response packet from host 127.0.0.1 port 61813 - ID 65
Debug output (3rd party server): Listening on acct address 127.0.0.1 port 61813 bound to server default Ready to process requests (0) Received Status-Server Id 65 from 127.0.0.1:39764 to 127.0.0.1:61813 length 70 (0) Message-Authenticator = 0x20f5e89b36552213c4f96e71f439cfea (0) NAS-Identifier = "Status Check 1. Are you alive?" (0) Sent Accounting-Response Id 65 from 127.0.0.1:61813 to 127.0.0.1:39764 length 0 (0) Finished request Waking up in 1.9 seconds. (0) <done>: Cleaning up request packet ID 65 with timestamp +4 Ready to process requests (1) Received Status-Server Id 21 from 127.0.0.1:39764 to 127.0.0.1:61813 length 70 (1) Message-Authenticator = 0x557c9db0ae54d9e837a06151a5f7d951 (1) NAS-Identifier = "Status Check 2. Are you alive?" (1) Sent Accounting-Response Id 21 from 127.0.0.1:61813 to 127.0.0.1:39764 length 0 (1) Finished request Waking up in 1.9 seconds.
On Fri, Aug 14, 2015 at 3:30 PM, Peter Balsianok < balsianok.peter@gmail.com> wrote:
[radiusd@tdrad1 acct-test]$ cat /etc/redhat-release Red Hat Enterprise Linux Server release 5.11 (Tikanga)
A virtual machine on the ESX server
Status-Server -> Yes i can try
On Fri, Aug 14, 2015 at 3:18 PM, Alan DeKok <aland@deployingradius.com> wrote:
On Aug 14, 2015, at 2:23 PM, Peter Balsianok <balsianok.peter@gmail.com> wrote:
Hmm... what kind of system are you running? i.e. is this a container? A plain OS? What is unusual about this?
Can you try using Status-Server packets for the checks, instead of Accounting-Request packets?
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
OK... that's just weird. What are you doing with the config? You're clearly in some unusual corner case which causes this problem. I can't see it here, and there have been no other reports. So... it works 99% of the time. What causes the problem? i.e. start with a default config, test that it works. Make one change to get it closer to your current config, test it again, etc. When it stops working, you've narrowed it down to the one change that causes the problem. You don't need to change much... just anything related to proxying and status checks. There's no need to look users up in a DB, etc. Unless I know what's different about your system, it will be impossible to understand what's going wrong. And therefore impossible to fix it. Alan DeKok.
Thank you for your advise Alan. I have changed DEFAULT configuration, but the problem is persisting :(. Debug output: [radiusd@tdrad1 acct-test-orig]$ ./run-debug.sh Mon Aug 17 09:43:09 2015 : Debug: Server was built with: Mon Aug 17 09:43:09 2015 : Debug: accounting : yes Mon Aug 17 09:43:09 2015 : Debug: authentication : yes Mon Aug 17 09:43:09 2015 : Debug: ascend-binary-attributes : yes Mon Aug 17 09:43:09 2015 : Debug: coa : yes Mon Aug 17 09:43:09 2015 : Debug: control-socket : yes Mon Aug 17 09:43:09 2015 : Debug: detail : yes Mon Aug 17 09:43:09 2015 : Debug: dhcp : yes Mon Aug 17 09:43:09 2015 : Debug: dynamic-clients : yes Mon Aug 17 09:43:09 2015 : Debug: osfc2 : no Mon Aug 17 09:43:09 2015 : Debug: proxy : yes Mon Aug 17 09:43:09 2015 : Debug: regex-pcre : no Mon Aug 17 09:43:09 2015 : Debug: regex-posix : yes Mon Aug 17 09:43:09 2015 : Debug: regex-posix-extended : yes Mon Aug 17 09:43:09 2015 : Debug: session-management : yes Mon Aug 17 09:43:09 2015 : Debug: stats : yes Mon Aug 17 09:43:09 2015 : Debug: tcp : yes Mon Aug 17 09:43:09 2015 : Debug: threads : yes Mon Aug 17 09:43:09 2015 : Debug: tls : yes Mon Aug 17 09:43:09 2015 : Debug: unlang : yes Mon Aug 17 09:43:09 2015 : Debug: vmps : yes Mon Aug 17 09:43:09 2015 : Debug: developer : yes Mon Aug 17 09:43:09 2015 : Debug: Server core libs: Mon Aug 17 09:43:09 2015 : Debug: freeradius-server : 3.0.10 Mon Aug 17 09:43:09 2015 : Debug: talloc : 2.0.* Mon Aug 17 09:43:09 2015 : Debug: ssl : 0.9.8b release Mon Aug 17 09:43:09 2015 : Debug: Endianess: Mon Aug 17 09:43:09 2015 : Debug: little Mon Aug 17 09:43:09 2015 : Debug: Compilation flags: Mon Aug 17 09:43:09 2015 : Info: Copyright (C) 1999-2015 The FreeRADIUS server project and contributors Mon Aug 17 09:43:09 2015 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A Mon Aug 17 09:43:09 2015 : Info: PARTICULAR PURPOSE Mon Aug 17 09:43:09 2015 : Info: You may redistribute copies of FreeRADIUS under the terms of the Mon Aug 17 09:43:09 2015 : Info: GNU General Public License Mon Aug 17 09:43:09 2015 : Info: For more information about these matters, see the file named COPYRIGHT Mon Aug 17 09:43:09 2015 : Info: Starting - reading configuration files ... Mon Aug 17 09:43:09 2015 : Debug: including dictionary file /app/radius/freeradius-3.0.9/share/freeradius/dictionary Mon Aug 17 09:43:09 2015 : Debug: including dictionary file /app/radius/freeradius-3.0.9/share/freeradius/dictionary.dhcp Mon Aug 17 09:43:09 2015 : Debug: including dictionary file /app/radius/freeradius-3.0.9/share/freeradius/dictionary.vqp Mon Aug 17 09:43:09 2015 : Debug: including dictionary file /app/radius/conf/acct-test-orig/dictionary Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/radiusd.conf Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/templates.conf Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/proxy.conf Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/clients.conf Mon Aug 17 09:43:09 2015 : Debug: including files in directory /app/radius/conf/acct-test-orig/mods-enabled/ Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/mods-enabled/files Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/mods-enabled/expr Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/mods-enabled/preprocess Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/mods-enabled/chap Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/mods-enabled/attr_filter Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/mods-enabled/perl Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/mods-enabled/realm Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/mods-enabled/pap Mon Aug 17 09:43:09 2015 : Debug: including files in directory /app/radius/conf/acct-test-orig/policy.d/ Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/policy.d/abfab-tr Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/policy.d/debug Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/policy.d/control Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/policy.d/eap Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/policy.d/canonicalization Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/policy.d/dhcp Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/policy.d/accounting Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/policy.d/cui Mon Aug 17 09:43:09 2015 : Debug: OPTIMIZING (${policy.cui_require_operator_name} == yes) --> FALSE Mon Aug 17 09:43:09 2015 : Debug: OPTIMIZING (no == yes) --> FALSE Mon Aug 17 09:43:09 2015 : Debug: OPTIMIZING (${policy.cui_require_operator_name} == yes) --> FALSE Mon Aug 17 09:43:09 2015 : Debug: OPTIMIZING (no == yes) --> FALSE Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/policy.d/operator-name Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/policy.d/filter Mon Aug 17 09:43:09 2015 : Debug: including files in directory /app/radius/conf/acct-test-orig/sites-enabled/ Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/sites-enabled/default Mon Aug 17 09:43:09 2015 : Debug: main { Mon Aug 17 09:43:09 2015 : Debug: name = "acct-test-orig" Mon Aug 17 09:43:09 2015 : Debug: prefix = "/app/radius/freeradius-3.0.9" Mon Aug 17 09:43:09 2015 : Debug: localstatedir = "/app_log/radius/acct-test-orig/" Mon Aug 17 09:43:09 2015 : Debug: sbindir = "/app/radius/freeradius-3.0.9/sbin" Mon Aug 17 09:43:09 2015 : Debug: logdir = "/app_log/radius/acct-test-orig/" Mon Aug 17 09:43:09 2015 : Debug: run_dir = "/app_log/radius/acct-test-orig/" Mon Aug 17 09:43:09 2015 : Debug: libdir = "/app/radius/freeradius-3.0.9/lib" Mon Aug 17 09:43:09 2015 : Debug: radacctdir = "/app_log/radius/acct-test-orig//radacct" Mon Aug 17 09:43:09 2015 : Debug: panic_action = "gdb -silent -x /app/radius/freeradius-3.0.9/../raddb/acct-test-orig/panic.gdb %e %p 2>&1 | tee /app_log/radius/acct-test-orig//gdb-acct-test-orig-%p.log" Mon Aug 17 09:43:09 2015 : Debug: hostname_lookups = no Mon Aug 17 09:43:09 2015 : Debug: max_request_time = 5 Mon Aug 17 09:43:09 2015 : Debug: cleanup_delay = 2 Mon Aug 17 09:43:09 2015 : Debug: max_requests = 25600 Mon Aug 17 09:43:09 2015 : Debug: pidfile = "/app_log/radius/acct-test-orig//radius.pid" Mon Aug 17 09:43:09 2015 : Debug: checkrad = "/app/radius/freeradius-3.0.9/sbin/checkrad" Mon Aug 17 09:43:09 2015 : Debug: debug_level = 0 Mon Aug 17 09:43:09 2015 : Debug: proxy_requests = yes Mon Aug 17 09:43:09 2015 : Debug: log { Mon Aug 17 09:43:09 2015 : Debug: stripped_names = no Mon Aug 17 09:43:09 2015 : Debug: auth = no Mon Aug 17 09:43:09 2015 : Debug: auth_badpass = no Mon Aug 17 09:43:09 2015 : Debug: auth_goodpass = no Mon Aug 17 09:43:09 2015 : Debug: colourise = yes Mon Aug 17 09:43:09 2015 : Debug: msg_denied = "You are already logged in - access denied" Mon Aug 17 09:43:09 2015 : Warning: /app/radius/conf/acct-test-orig/radiusd.conf[272]: The item 'destination' is defined, but is unused by the configuration Mon Aug 17 09:43:09 2015 : Warning: /app/radius/conf/acct-test-orig/radiusd.conf[289]: The item 'file' is defined, but is unused by the configuration Mon Aug 17 09:43:09 2015 : Warning: /app/radius/conf/acct-test-orig/radiusd.conf[335]: The item 'syslog_facility' is defined, but is unused by the configuration Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: resources { Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: security { Mon Aug 17 09:43:09 2015 : Debug: max_attributes = 200 Mon Aug 17 09:43:09 2015 : Debug: reject_delay = 0.000000 Mon Aug 17 09:43:09 2015 : Debug: status_server = yes Mon Aug 17 09:43:09 2015 : Debug: allow_vulnerable_openssl = "yes" Mon Aug 17 09:43:09 2015 : Warning: /app/radius/conf/acct-test-orig/radiusd.conf[451]: The item 'allow_core_dumps' is defined, but is unused by the configuration Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Warning: /app/radius/conf/acct-test-orig/radiusd.conf[67]: The item 'confdir' is defined, but is unused by the configuration Mon Aug 17 09:43:09 2015 : Warning: /app/radius/conf/acct-test-orig/radiusd.conf[69]: The item 'certdir' is defined, but is unused by the configuration Mon Aug 17 09:43:09 2015 : Warning: /app/radius/conf/acct-test-orig/radiusd.conf[70]: The item 'cadir' is defined, but is unused by the configuration Mon Aug 17 09:43:09 2015 : Warning: /app/radius/conf/acct-test-orig/radiusd.conf[72]: The item 'loader_dir' is defined, but is unused by the configuration Mon Aug 17 09:43:09 2015 : Warning: /app/radius/conf/acct-test-orig/radiusd.conf[74]: The item 'notification_dir' is defined, but is unused by the configuration Mon Aug 17 09:43:09 2015 : Warning: /app/radius/conf/acct-test-orig/radiusd.conf[78]: The item 'db_dir' is defined, but is unused by the configuration Mon Aug 17 09:43:09 2015 : Warning: /app/radius/conf/acct-test-orig/radiusd.conf[144]: The item 'correct_escapes' is defined, but is unused by the configuration Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: radiusd: #### Loading Realms and Home Servers #### Mon Aug 17 09:43:09 2015 : Debug: proxy server { Mon Aug 17 09:43:09 2015 : Debug: retry_delay = 5 Mon Aug 17 09:43:09 2015 : Debug: retry_count = 3 Mon Aug 17 09:43:09 2015 : Debug: default_fallback = no Mon Aug 17 09:43:09 2015 : Debug: dead_time = 120 Mon Aug 17 09:43:09 2015 : Debug: wake_all_if_all_dead = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: home_server localhostA { Mon Aug 17 09:43:09 2015 : Debug: ipaddr = 127.0.0.1 Mon Aug 17 09:43:09 2015 : Debug: port = 60813 Mon Aug 17 09:43:09 2015 : Debug: type = "acct" Mon Aug 17 09:43:09 2015 : Debug: secret = "test123test" Mon Aug 17 09:43:09 2015 : Debug: response_window = 20.000000 Mon Aug 17 09:43:09 2015 : Debug: response_timeouts = 1 Mon Aug 17 09:43:09 2015 : Debug: max_outstanding = 65536 Mon Aug 17 09:43:09 2015 : Debug: zombie_period = 40 Mon Aug 17 09:43:09 2015 : Debug: status_check = "status-server" Mon Aug 17 09:43:09 2015 : Debug: ping_interval = 30 Mon Aug 17 09:43:09 2015 : Debug: check_interval = 30 Mon Aug 17 09:43:09 2015 : Debug: check_timeout = 4 Mon Aug 17 09:43:09 2015 : Debug: num_answers_to_alive = 3 Mon Aug 17 09:43:09 2015 : Debug: revive_interval = 120 Mon Aug 17 09:43:09 2015 : Debug: limit { Mon Aug 17 09:43:09 2015 : Debug: max_connections = 16 Mon Aug 17 09:43:09 2015 : Debug: max_requests = 0 Mon Aug 17 09:43:09 2015 : Debug: lifetime = 0 Mon Aug 17 09:43:09 2015 : Debug: idle_timeout = 0 Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: coa { Mon Aug 17 09:43:09 2015 : Debug: irt = 2 Mon Aug 17 09:43:09 2015 : Debug: mrt = 16 Mon Aug 17 09:43:09 2015 : Debug: mrc = 5 Mon Aug 17 09:43:09 2015 : Debug: mrd = 30 Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Warning: WARNING: Ignoring "response_window = 20.000000", forcing to "response_window = 5.000000" Mon Aug 17 09:43:09 2015 : Debug: home_server_pool my_acct_failover { Mon Aug 17 09:43:09 2015 : Debug: type = fail-over Mon Aug 17 09:43:09 2015 : Debug: home_server = localhostA Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: realm testproxy.sk { Mon Aug 17 09:43:09 2015 : Debug: acct_pool = my_acct_failover Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: realm LOCAL { Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: radiusd: #### Loading Clients #### Mon Aug 17 09:43:09 2015 : Debug: client localhost { Mon Aug 17 09:43:09 2015 : Debug: ipaddr = 127.0.0.1 Mon Aug 17 09:43:09 2015 : Debug: require_message_authenticator = no Mon Aug 17 09:43:09 2015 : Debug: secret = "test123test" Mon Aug 17 09:43:09 2015 : Debug: nas_type = "other" Mon Aug 17 09:43:09 2015 : Debug: proto = "*" Mon Aug 17 09:43:09 2015 : Debug: limit { Mon Aug 17 09:43:09 2015 : Debug: max_connections = 16 Mon Aug 17 09:43:09 2015 : Debug: lifetime = 0 Mon Aug 17 09:43:09 2015 : Debug: idle_timeout = 30 Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: Adding client 127.0.0.1/32 (127.0.0.1) to prefix tree 32 Mon Aug 17 09:43:09 2015 : Debug: client localhost_ipv6 { Mon Aug 17 09:43:09 2015 : Debug: ipv6addr = ::1 Mon Aug 17 09:43:09 2015 : Debug: require_message_authenticator = no Mon Aug 17 09:43:09 2015 : Debug: secret = "testing123" Mon Aug 17 09:43:09 2015 : Debug: limit { Mon Aug 17 09:43:09 2015 : Debug: max_connections = 16 Mon Aug 17 09:43:09 2015 : Debug: lifetime = 0 Mon Aug 17 09:43:09 2015 : Debug: idle_timeout = 30 Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: Adding client ::1/128 (::1) to prefix tree 128 Mon Aug 17 09:43:09 2015 : Info: Debugger not attached Mon Aug 17 09:43:09 2015 : Debug: radiusd: #### Instantiating modules #### Mon Aug 17 09:43:09 2015 : Debug: Loading library using absolute path "/app/radius/freeradius-3.0.9/lib/rlm_files.so" Mon Aug 17 09:43:09 2015 : Debug: Loaded rlm_files, checking if it's valid Mon Aug 17 09:43:09 2015 : Debug: # Loaded module rlm_files Mon Aug 17 09:43:09 2015 : Debug: # Loading module "files" from file /app/radius/conf/acct-test-orig/mods-enabled/files Mon Aug 17 09:43:09 2015 : Debug: files { Mon Aug 17 09:43:09 2015 : Debug: filename = "/app/radius/conf/acct-test-orig/mods-config/files/authorize" Mon Aug 17 09:43:09 2015 : Debug: acctusersfile = "/app/radius/conf/acct-test-orig/mods-config/files/accounting" Mon Aug 17 09:43:09 2015 : Debug: preproxy_usersfile = "/app/radius/conf/acct-test-orig/mods-config/files/pre-proxy" Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: Loading library using absolute path "/app/radius/freeradius-3.0.9/lib/rlm_expr.so" Mon Aug 17 09:43:09 2015 : Debug: Loaded rlm_expr, checking if it's valid Mon Aug 17 09:43:09 2015 : Debug: # Loaded module rlm_expr Mon Aug 17 09:43:09 2015 : Debug: # Loading module "expr" from file /app/radius/conf/acct-test-orig/mods-enabled/expr Mon Aug 17 09:43:09 2015 : Debug: expr { Mon Aug 17 09:43:09 2015 : Debug: safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /äéöüàâæçèéêëîïôœùûüaÿÄÉÖÜßÀÂÆÇÈÉÊËÎÏÔŒÙÛÜŸ" Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: Loading library using absolute path "/app/radius/freeradius-3.0.9/lib/rlm_preprocess.so" Mon Aug 17 09:43:09 2015 : Debug: Loaded rlm_preprocess, checking if it's valid Mon Aug 17 09:43:09 2015 : Debug: # Loaded module rlm_preprocess Mon Aug 17 09:43:09 2015 : Debug: # Loading module "preprocess" from file /app/radius/conf/acct-test-orig/mods-enabled/preprocess Mon Aug 17 09:43:09 2015 : Debug: preprocess { Mon Aug 17 09:43:09 2015 : Debug: huntgroups = "/app/radius/conf/acct-test-orig/mods-config/preprocess/huntgroups" Mon Aug 17 09:43:09 2015 : Debug: hints = "/app/radius/conf/acct-test-orig/mods-config/preprocess/hints" Mon Aug 17 09:43:09 2015 : Debug: with_ascend_hack = no Mon Aug 17 09:43:09 2015 : Debug: ascend_channels_per_line = 23 Mon Aug 17 09:43:09 2015 : Debug: with_ntdomain_hack = no Mon Aug 17 09:43:09 2015 : Debug: with_specialix_jetstream_hack = no Mon Aug 17 09:43:09 2015 : Debug: with_cisco_vsa_hack = no Mon Aug 17 09:43:09 2015 : Debug: with_alvarion_vsa_hack = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: Loading library using absolute path "/app/radius/freeradius-3.0.9/lib/rlm_chap.so" Mon Aug 17 09:43:09 2015 : Debug: Loaded rlm_chap, checking if it's valid Mon Aug 17 09:43:09 2015 : Debug: # Loaded module rlm_chap Mon Aug 17 09:43:09 2015 : Debug: # Loading module "chap" from file /app/radius/conf/acct-test-orig/mods-enabled/chap Mon Aug 17 09:43:09 2015 : Debug: Loading library using absolute path "/app/radius/freeradius-3.0.9/lib/rlm_attr_filter.so" Mon Aug 17 09:43:09 2015 : Debug: Loaded rlm_attr_filter, checking if it's valid Mon Aug 17 09:43:09 2015 : Debug: # Loaded module rlm_attr_filter Mon Aug 17 09:43:09 2015 : Debug: # Loading module "attr_filter.post-proxy" from file /app/radius/conf/acct-test-orig/mods-enabled/attr_filter Mon Aug 17 09:43:09 2015 : Debug: attr_filter attr_filter.post-proxy { Mon Aug 17 09:43:09 2015 : Debug: filename = "/app/radius/conf/acct-test-orig/mods-config/attr_filter/post-proxy" Mon Aug 17 09:43:09 2015 : Debug: key = "%{Realm}" Mon Aug 17 09:43:09 2015 : Debug: relaxed = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "attr_filter.pre-proxy" from file /app/radius/conf/acct-test-orig/mods-enabled/attr_filter Mon Aug 17 09:43:09 2015 : Debug: attr_filter attr_filter.pre-proxy { Mon Aug 17 09:43:09 2015 : Debug: filename = "/app/radius/conf/acct-test-orig/mods-config/attr_filter/pre-proxy" Mon Aug 17 09:43:09 2015 : Debug: key = "%{Realm}" Mon Aug 17 09:43:09 2015 : Debug: relaxed = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "attr_filter.access_reject" from file /app/radius/conf/acct-test-orig/mods-enabled/attr_filter Mon Aug 17 09:43:09 2015 : Debug: attr_filter attr_filter.access_reject { Mon Aug 17 09:43:09 2015 : Debug: filename = "/app/radius/conf/acct-test-orig/mods-config/attr_filter/access_reject" Mon Aug 17 09:43:09 2015 : Debug: key = "%{User-Name}" Mon Aug 17 09:43:09 2015 : Debug: relaxed = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "attr_filter.access_challenge" from file /app/radius/conf/acct-test-orig/mods-enabled/attr_filter Mon Aug 17 09:43:09 2015 : Debug: attr_filter attr_filter.access_challenge { Mon Aug 17 09:43:09 2015 : Debug: filename = "/app/radius/conf/acct-test-orig/mods-config/attr_filter/access_challenge" Mon Aug 17 09:43:09 2015 : Debug: key = "%{User-Name}" Mon Aug 17 09:43:09 2015 : Debug: relaxed = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "attr_filter.accounting_response" from file /app/radius/conf/acct-test-orig/mods-enabled/attr_filter Mon Aug 17 09:43:09 2015 : Debug: attr_filter attr_filter.accounting_response { Mon Aug 17 09:43:09 2015 : Debug: filename = "/app/radius/conf/acct-test-orig/mods-config/attr_filter/accounting_response" Mon Aug 17 09:43:09 2015 : Debug: key = "%{User-Name}" Mon Aug 17 09:43:09 2015 : Debug: relaxed = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: Loading library using absolute path "/app/radius/freeradius-3.0.9/lib/rlm_always.so" Mon Aug 17 09:43:09 2015 : Debug: Loaded rlm_always, checking if it's valid Mon Aug 17 09:43:09 2015 : Debug: # Loaded module rlm_always Mon Aug 17 09:43:09 2015 : Debug: # Loading module "reject" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: always reject { Mon Aug 17 09:43:09 2015 : Debug: rcode = "reject" Mon Aug 17 09:43:09 2015 : Debug: simulcount = 0 Mon Aug 17 09:43:09 2015 : Debug: mpp = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "fail" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: always fail { Mon Aug 17 09:43:09 2015 : Debug: rcode = "fail" Mon Aug 17 09:43:09 2015 : Debug: simulcount = 0 Mon Aug 17 09:43:09 2015 : Debug: mpp = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "ok" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: always ok { Mon Aug 17 09:43:09 2015 : Debug: rcode = "ok" Mon Aug 17 09:43:09 2015 : Debug: simulcount = 0 Mon Aug 17 09:43:09 2015 : Debug: mpp = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "handled" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: always handled { Mon Aug 17 09:43:09 2015 : Debug: rcode = "handled" Mon Aug 17 09:43:09 2015 : Debug: simulcount = 0 Mon Aug 17 09:43:09 2015 : Debug: mpp = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "invalid" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: always invalid { Mon Aug 17 09:43:09 2015 : Debug: rcode = "invalid" Mon Aug 17 09:43:09 2015 : Debug: simulcount = 0 Mon Aug 17 09:43:09 2015 : Debug: mpp = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "userlock" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: always userlock { Mon Aug 17 09:43:09 2015 : Debug: rcode = "userlock" Mon Aug 17 09:43:09 2015 : Debug: simulcount = 0 Mon Aug 17 09:43:09 2015 : Debug: mpp = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "notfound" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: always notfound { Mon Aug 17 09:43:09 2015 : Debug: rcode = "notfound" Mon Aug 17 09:43:09 2015 : Debug: simulcount = 0 Mon Aug 17 09:43:09 2015 : Debug: mpp = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "noop" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: always noop { Mon Aug 17 09:43:09 2015 : Debug: rcode = "noop" Mon Aug 17 09:43:09 2015 : Debug: simulcount = 0 Mon Aug 17 09:43:09 2015 : Debug: mpp = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "updated" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: always updated { Mon Aug 17 09:43:09 2015 : Debug: rcode = "updated" Mon Aug 17 09:43:09 2015 : Debug: simulcount = 0 Mon Aug 17 09:43:09 2015 : Debug: mpp = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: Loading library using absolute path "/app/radius/freeradius-3.0.9/lib/rlm_perl.so" Mon Aug 17 09:43:09 2015 : Debug: Loaded rlm_perl, checking if it's valid Mon Aug 17 09:43:09 2015 : Debug: # Loaded module rlm_perl Mon Aug 17 09:43:09 2015 : Debug: # Loading module "perl" from file /app/radius/conf/acct-test-orig/mods-enabled/perl Mon Aug 17 09:43:09 2015 : Debug: perl { Mon Aug 17 09:43:09 2015 : Debug: filename = "/app/radius/conf/acct-test-orig/mods-config/perl/example.pl" Mon Aug 17 09:43:09 2015 : Debug: func_authorize = "authorize" Mon Aug 17 09:43:09 2015 : Debug: func_authenticate = "authenticate" Mon Aug 17 09:43:09 2015 : Debug: func_post_auth = "post_auth" Mon Aug 17 09:43:09 2015 : Debug: func_accounting = "accounting" Mon Aug 17 09:43:09 2015 : Debug: func_preacct = "preacct" Mon Aug 17 09:43:09 2015 : Debug: func_checksimul = "checksimul" Mon Aug 17 09:43:09 2015 : Debug: func_detach = "detach" Mon Aug 17 09:43:09 2015 : Debug: func_xlat = "xlat" Mon Aug 17 09:43:09 2015 : Debug: func_pre_proxy = "pre_proxy" Mon Aug 17 09:43:09 2015 : Debug: func_post_proxy = "post_proxy" Mon Aug 17 09:43:09 2015 : Debug: func_recv_coa = "recv_coa" Mon Aug 17 09:43:09 2015 : Debug: func_send_coa = "send_coa" Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: Loading library using absolute path "/app/radius/freeradius-3.0.9/lib/rlm_realm.so" Mon Aug 17 09:43:09 2015 : Debug: Loaded rlm_realm, checking if it's valid Mon Aug 17 09:43:09 2015 : Debug: # Loaded module rlm_realm Mon Aug 17 09:43:09 2015 : Debug: # Loading module "IPASS" from file /app/radius/conf/acct-test-orig/mods-enabled/realm Mon Aug 17 09:43:09 2015 : Debug: realm IPASS { Mon Aug 17 09:43:09 2015 : Debug: format = "prefix" Mon Aug 17 09:43:09 2015 : Debug: delimiter = "/" Mon Aug 17 09:43:09 2015 : Debug: ignore_default = no Mon Aug 17 09:43:09 2015 : Debug: ignore_null = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "suffix" from file /app/radius/conf/acct-test-orig/mods-enabled/realm Mon Aug 17 09:43:09 2015 : Debug: realm suffix { Mon Aug 17 09:43:09 2015 : Debug: format = "suffix" Mon Aug 17 09:43:09 2015 : Debug: delimiter = "@" Mon Aug 17 09:43:09 2015 : Debug: ignore_default = no Mon Aug 17 09:43:09 2015 : Debug: ignore_null = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "realmpercent" from file /app/radius/conf/acct-test-orig/mods-enabled/realm Mon Aug 17 09:43:09 2015 : Debug: realm realmpercent { Mon Aug 17 09:43:09 2015 : Debug: format = "suffix" Mon Aug 17 09:43:09 2015 : Debug: delimiter = "%" Mon Aug 17 09:43:09 2015 : Debug: ignore_default = no Mon Aug 17 09:43:09 2015 : Debug: ignore_null = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "ntdomain" from file /app/radius/conf/acct-test-orig/mods-enabled/realm Mon Aug 17 09:43:09 2015 : Debug: realm ntdomain { Mon Aug 17 09:43:09 2015 : Debug: format = "prefix" Mon Aug 17 09:43:09 2015 : Debug: delimiter = "\\" Mon Aug 17 09:43:09 2015 : Debug: ignore_default = no Mon Aug 17 09:43:09 2015 : Debug: ignore_null = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: Loading library using absolute path "/app/radius/freeradius-3.0.9/lib/rlm_pap.so" Mon Aug 17 09:43:09 2015 : Debug: Loaded rlm_pap, checking if it's valid Mon Aug 17 09:43:09 2015 : Debug: # Loaded module rlm_pap Mon Aug 17 09:43:09 2015 : Debug: # Loading module "pap" from file /app/radius/conf/acct-test-orig/mods-enabled/pap Mon Aug 17 09:43:09 2015 : Debug: pap { Mon Aug 17 09:43:09 2015 : Debug: normalise = yes Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: instantiate { Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "perl" from file /app/radius/conf/acct-test-orig/mods-enabled/perl Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: modules { Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "files" from file /app/radius/conf/acct-test-orig/mods-enabled/files Mon Aug 17 09:43:09 2015 : Debug: reading pairlist file /app/radius/conf/acct-test-orig/mods-config/files/authorize Mon Aug 17 09:43:09 2015 : Debug: reading pairlist file /app/radius/conf/acct-test-orig/mods-config/files/accounting Mon Aug 17 09:43:09 2015 : Debug: reading pairlist file /app/radius/conf/acct-test-orig/mods-config/files/pre-proxy Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "preprocess" from file /app/radius/conf/acct-test-orig/mods-enabled/preprocess Mon Aug 17 09:43:09 2015 : Debug: reading pairlist file /app/radius/conf/acct-test-orig/mods-config/preprocess/huntgroups Mon Aug 17 09:43:09 2015 : Debug: reading pairlist file /app/radius/conf/acct-test-orig/mods-config/preprocess/hints Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "attr_filter.post-proxy" from file /app/radius/conf/acct-test-orig/mods-enabled/attr_filter Mon Aug 17 09:43:09 2015 : Debug: reading pairlist file /app/radius/conf/acct-test-orig/mods-config/attr_filter/post-proxy Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "attr_filter.pre-proxy" from file /app/radius/conf/acct-test-orig/mods-enabled/attr_filter Mon Aug 17 09:43:09 2015 : Debug: reading pairlist file /app/radius/conf/acct-test-orig/mods-config/attr_filter/pre-proxy Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "attr_filter.access_reject" from file /app/radius/conf/acct-test-orig/mods-enabled/attr_filter Mon Aug 17 09:43:09 2015 : Debug: reading pairlist file /app/radius/conf/acct-test-orig/mods-config/attr_filter/access_reject Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "attr_filter.access_challenge" from file /app/radius/conf/acct-test-orig/mods-enabled/attr_filter Mon Aug 17 09:43:09 2015 : Debug: reading pairlist file /app/radius/conf/acct-test-orig/mods-config/attr_filter/access_challenge Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "attr_filter.accounting_response" from file /app/radius/conf/acct-test-orig/mods-enabled/attr_filter Mon Aug 17 09:43:09 2015 : Debug: reading pairlist file /app/radius/conf/acct-test-orig/mods-config/attr_filter/accounting_response Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "reject" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "fail" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "ok" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "handled" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "invalid" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "userlock" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "notfound" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "noop" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "updated" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "IPASS" from file /app/radius/conf/acct-test-orig/mods-enabled/realm Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "suffix" from file /app/radius/conf/acct-test-orig/mods-enabled/realm Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "realmpercent" from file /app/radius/conf/acct-test-orig/mods-enabled/realm Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "ntdomain" from file /app/radius/conf/acct-test-orig/mods-enabled/realm Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "pap" from file /app/radius/conf/acct-test-orig/mods-enabled/pap Mon Aug 17 09:43:09 2015 : Debug: } # modules Mon Aug 17 09:43:09 2015 : Debug: radiusd: #### Loading Virtual Servers #### Mon Aug 17 09:43:09 2015 : Debug: server { # from file /app/radius/conf/acct-test-orig/radiusd.conf Mon Aug 17 09:43:09 2015 : Debug: } # server Mon Aug 17 09:43:09 2015 : Debug: server default { # from file /app/radius/conf/acct-test-orig/sites-enabled/default Mon Aug 17 09:43:09 2015 : Debug: authenticate { Mon Aug 17 09:43:09 2015 : Debug: group { Mon Aug 17 09:43:09 2015 : Debug: pap Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: group { Mon Aug 17 09:43:09 2015 : Debug: chap Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: } # authenticate Mon Aug 17 09:43:09 2015 : Debug: authorize { Mon Aug 17 09:43:09 2015 : Debug: policy filter_username { Mon Aug 17 09:43:09 2015 : Debug: if (!&User-Name) { Mon Aug 17 09:43:09 2015 : Debug: noop Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: if (&User-Name =~ / /) { Mon Aug 17 09:43:09 2015 : Debug: update { Mon Aug 17 09:43:09 2015 : Debug: &reply:Reply-Message += 'Rejected: Username contains whitespace' Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: reject Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: if (&User-Name =~ /@.*@/) { Mon Aug 17 09:43:09 2015 : Debug: update { Mon Aug 17 09:43:09 2015 : Debug: &reply:Reply-Message += 'Rejected: Multiple @ in username' Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: reject Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: if (&User-Name =~ /\.\./) { Mon Aug 17 09:43:09 2015 : Debug: update { Mon Aug 17 09:43:09 2015 : Debug: &reply:Reply-Message += 'Rejected: Username contains ..s' Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: reject Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: if (&User-Name =~ /@/ && !&User-Name =~ /@(.+)\.(.+)$/) { Mon Aug 17 09:43:09 2015 : Debug: update { Mon Aug 17 09:43:09 2015 : Debug: &reply:Reply-Message += 'Rejected: Realm does not have at least one dot separator' Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: reject Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: if (&User-Name =~ /\.$/) { Mon Aug 17 09:43:09 2015 : Debug: update { Mon Aug 17 09:43:09 2015 : Debug: &reply:Reply-Message += 'Rejected: Realm ends with a dot' Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: reject Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: if (&User-Name =~ /@\./) { Mon Aug 17 09:43:09 2015 : Debug: update { Mon Aug 17 09:43:09 2015 : Debug: &reply:Reply-Message += 'Rejected: Realm begins with a dot' Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: reject Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: preprocess Mon Aug 17 09:43:09 2015 : Debug: chap Mon Aug 17 09:43:09 2015 : Debug: suffix Mon Aug 17 09:43:09 2015 : Debug: files Mon Aug 17 09:43:09 2015 : Warning: Ignoring "sql" (see raddb/mods-available/README.rst) Mon Aug 17 09:43:09 2015 : Warning: Ignoring "ldap" (see raddb/mods-available/README.rst) Mon Aug 17 09:43:09 2015 : Debug: pap Mon Aug 17 09:43:09 2015 : Debug: } # authorize Mon Aug 17 09:43:09 2015 : Debug: preacct { Mon Aug 17 09:43:09 2015 : Debug: preprocess Mon Aug 17 09:43:09 2015 : Debug: policy acct_unique { Mon Aug 17 09:43:09 2015 : Debug: if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/) { Mon Aug 17 09:43:09 2015 : Debug: update { Mon Aug 17 09:43:09 2015 : Debug: &Acct-Unique-Session-Id := "%{md5:%{1},%{Acct-Session-ID}}" Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: else { Mon Aug 17 09:43:09 2015 : Debug: update { Mon Aug 17 09:43:09 2015 : Debug: &Acct-Unique-Session-Id := "%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}" Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: suffix Mon Aug 17 09:43:09 2015 : Debug: files Mon Aug 17 09:43:09 2015 : Debug: } # preacct Mon Aug 17 09:43:09 2015 : Debug: accounting { Mon Aug 17 09:43:09 2015 : Debug: attr_filter.accounting_response Mon Aug 17 09:43:09 2015 : Debug: } # accounting Mon Aug 17 09:43:09 2015 : Debug: post-auth { Mon Aug 17 09:43:09 2015 : Debug: update { Mon Aug 17 09:43:09 2015 : Debug: &reply[*] += &session-state[*] Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: group { Mon Aug 17 09:43:09 2015 : Debug: attr_filter.access_reject Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: } # post-auth Mon Aug 17 09:43:09 2015 : Debug: } # server default Mon Aug 17 09:43:09 2015 : Debug: Created signal pipe. Read end FD 5, write end FD 6 Mon Aug 17 09:43:09 2015 : Debug: radiusd: #### Opening IP addresses and Ports #### Mon Aug 17 09:43:09 2015 : Debug: Loading library using absolute path "/app/radius/freeradius-3.0.9/lib/proto_acct.so" Mon Aug 17 09:43:09 2015 : Debug: Failed with error: /app/radius/freeradius-3.0.9/lib/proto_acct.so: cannot open shared object file: No such file or directory Mon Aug 17 09:43:09 2015 : Debug: Library file not found Mon Aug 17 09:43:09 2015 : Debug: Loading library using linker search path(s) Mon Aug 17 09:43:09 2015 : Debug: Defaults : /lib:/usr/lib Mon Aug 17 09:43:09 2015 : Debug: Failed with error: proto_acct.so: cannot open shared object file: No such file or directory Mon Aug 17 09:43:09 2015 : Debug: listen { Mon Aug 17 09:43:09 2015 : Debug: type = "acct" Mon Aug 17 09:43:09 2015 : Debug: ipaddr = * Mon Aug 17 09:43:09 2015 : Debug: port = 10813 Mon Aug 17 09:43:09 2015 : Debug: limit { Mon Aug 17 09:43:09 2015 : Debug: max_connections = 16 Mon Aug 17 09:43:09 2015 : Debug: lifetime = 0 Mon Aug 17 09:43:09 2015 : Debug: idle_timeout = 30 Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: Listening on acct address * port 10813 bound to server default Mon Aug 17 09:43:09 2015 : Debug: Opening new proxy socket 'proxy address * port 0' Mon Aug 17 09:43:09 2015 : Debug: Listening on proxy address * port 34833 Mon Aug 17 09:43:09 2015 : Info: Ready to process requests Socket: 7 Proto: 0 Src IP: 127.0.0.1 port: 43842 Dst IP: 127.0.0.1 port: 10813 Code: 4 Id: 94 Length: 219 Vector: ec9b6b7be6d6df3ec7718bfcbccce9cd Data: 01 1a 6d 6f 6e 2d 7a 64 72 6f 6a 65 31 40 74 65 73 74 70 72 6f 78 79 2e 73 6b 04 06 d5 97 d8 c9 20 17 67 67 73 6e 2d 30 31 2d 62 62 31 2e 6f 72 61 6e 67 65 2e 73 6b 3d 06 00 00 00 05 28 06 00 00 00 01 1e 0c 70 72 6f 78 79 2e 63 6f 72 70 1f 0e 34 32 31 39 30 35 30 36 36 30 30 31 2c 12 64 35 39 37 64 39 31 35 32 33 39 32 30 38 34 30 32 12 64 35 39 37 64 39 31 35 31 31 63 32 38 30 32 34 33 06 00 00 00 01 08 06 ac 17 44 0b 06 06 00 00 00 02 07 06 00 00 00 07 2d 06 00 00 00 01 e2 06 00 00 00 08 e0 0a 32 01 91 04 60 09 98 f8 e3 0c 3c 44 35 3e 3c 39 37 3e d9 15 e1 06 23 92 08 40 e4 06 d5 97 fc 18 Mon Aug 17 09:43:12 2015 : Debug: (0) Received Accounting-Request Id 94 from 127.0.0.1:43842 to 127.0.0.1:10813 length 219 Mon Aug 17 09:43:12 2015 : Debug: (0) User-Name = " mon-zdroje1@testproxy.sk" Mon Aug 17 09:43:12 2015 : Debug: (0) NAS-IP-Address = 213.151.216.201 Mon Aug 17 09:43:12 2015 : Debug: (0) NAS-Identifier = " ggsn-01-bb1.orange.sk" Mon Aug 17 09:43:12 2015 : Debug: (0) NAS-Port-Type = Virtual Mon Aug 17 09:43:12 2015 : Debug: (0) Acct-Status-Type = Start Mon Aug 17 09:43:12 2015 : Debug: (0) Called-Station-Id = "proxy.corp" Mon Aug 17 09:43:12 2015 : Debug: (0) Calling-Station-Id = "421905066001" Mon Aug 17 09:43:12 2015 : Debug: (0) Acct-Session-Id = "d597d91523920840" Mon Aug 17 09:43:12 2015 : Debug: (0) Acct-Multi-Session-Id = "d597d91511c28024" Mon Aug 17 09:43:12 2015 : Debug: (0) Acct-Link-Count = 1 Mon Aug 17 09:43:12 2015 : Debug: (0) Framed-IP-Address = 172.23.68.11 Mon Aug 17 09:43:12 2015 : Debug: (0) Service-Type = Framed-User Mon Aug 17 09:43:12 2015 : Debug: (0) Framed-Protocol = GPRS-PDP-Context Mon Aug 17 09:43:12 2015 : Debug: (0) Acct-Authentic = RADIUS Mon Aug 17 09:43:12 2015 : Debug: (0) X-Ascend-PRI-Number-Type = 8 Mon Aug 17 09:43:12 2015 : Debug: (0) Attr-224 = 0x32019104600998f8 Mon Aug 17 09:43:12 2015 : Debug: (0) X-Ascend-Dial-Number = "<D5><97>\331\025" Mon Aug 17 09:43:12 2015 : Debug: (0) X-Ascend-Metric = 596772928 Mon Aug 17 09:43:12 2015 : Debug: (0) X-Ascend-Route-IP = 3583507480 Mon Aug 17 09:43:12 2015 : Debug: (0) # Executing section preacct from file /app/radius/conf/acct-test-orig/sites-enabled/default Mon Aug 17 09:43:12 2015 : Debug: (0) preacct { Mon Aug 17 09:43:12 2015 : Debug: (0) modsingle[preacct]: calling preprocess (rlm_preprocess) for request 0 Mon Aug 17 09:43:12 2015 : Debug: (0) modsingle[preacct]: returned from preprocess (rlm_preprocess) for request 0 Mon Aug 17 09:43:12 2015 : Debug: (0) [preprocess] = ok Mon Aug 17 09:43:12 2015 : Debug: (0) policy acct_unique { Mon Aug 17 09:43:12 2015 : Debug: (0) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) { Mon Aug 17 09:43:12 2015 : Debug: (0) EXPAND TMPL XLAT STRUCT Mon Aug 17 09:43:12 2015 : Debug: (0) EXPAND %{string:Class} Mon Aug 17 09:43:12 2015 : Debug: (0) --> Mon Aug 17 09:43:12 2015 : Debug: No matches Mon Aug 17 09:43:12 2015 : Debug: (0) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) -> FALSE Mon Aug 17 09:43:12 2015 : Debug: (0) else { Mon Aug 17 09:43:12 2015 : Debug: (0) update request { Mon Aug 17 09:43:12 2015 : Debug: (0) EXPAND %{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}} Mon Aug 17 09:43:12 2015 : Debug: (0) --> 772f7c0824d05fe594797a68d34c3161 Mon Aug 17 09:43:12 2015 : Debug: (0) &Acct-Unique-Session-Id := 772f7c0824d05fe594797a68d34c3161 Mon Aug 17 09:43:12 2015 : Debug: (0) } # update request = noop Mon Aug 17 09:43:12 2015 : Debug: (0) } # else = noop Mon Aug 17 09:43:12 2015 : Debug: (0) } # policy acct_unique = noop Mon Aug 17 09:43:12 2015 : Debug: (0) modsingle[preacct]: calling suffix (rlm_realm) for request 0 Mon Aug 17 09:43:12 2015 : Debug: (0) suffix: Checking for suffix after "@" Mon Aug 17 09:43:12 2015 : Debug: (0) suffix: Looking up realm "testproxy.sk" for User-Name = "mon-zdroje1@testproxy.sk" Mon Aug 17 09:43:12 2015 : Debug: (0) suffix: Found realm "testproxy.sk" Mon Aug 17 09:43:12 2015 : Debug: (0) suffix: Adding Stripped-User-Name = "mon-zdroje1" Mon Aug 17 09:43:12 2015 : Debug: (0) suffix: Adding Realm = "testproxy.sk" Mon Aug 17 09:43:12 2015 : Debug: (0) suffix: Proxying request from user mon-zdroje1 to realm testproxy.sk Mon Aug 17 09:43:12 2015 : Debug: (0) suffix: Preparing to proxy accounting request to realm "testproxy.sk" Mon Aug 17 09:43:12 2015 : Debug: (0) modsingle[preacct]: returned from suffix (rlm_realm) for request 0 Mon Aug 17 09:43:12 2015 : Debug: (0) [suffix] = updated Mon Aug 17 09:43:12 2015 : Debug: (0) modsingle[preacct]: calling files (rlm_files) for request 0 Mon Aug 17 09:43:12 2015 : Debug: (0) modsingle[preacct]: returned from files (rlm_files) for request 0 Mon Aug 17 09:43:12 2015 : Debug: (0) [files] = noop Mon Aug 17 09:43:12 2015 : Debug: (0) } # preacct = updated Mon Aug 17 09:43:12 2015 : Debug: (0) # Executing section accounting from file /app/radius/conf/acct-test-orig/sites-enabled/default Mon Aug 17 09:43:12 2015 : Debug: (0) accounting { Mon Aug 17 09:43:12 2015 : Debug: (0) modsingle[accounting]: calling attr_filter.accounting_response (rlm_attr_filter) for request 0 Mon Aug 17 09:43:12 2015 : Debug: %{User-Name} Mon Aug 17 09:43:12 2015 : Debug: Parsed xlat tree: Mon Aug 17 09:43:12 2015 : Debug: attribute --> User-Name Mon Aug 17 09:43:12 2015 : Debug: (0) attr_filter.accounting_response: EXPAND %{User-Name} Mon Aug 17 09:43:12 2015 : Debug: (0) attr_filter.accounting_response: --> mon-zdroje1@testproxy.sk Mon Aug 17 09:43:12 2015 : Debug: (0) attr_filter.accounting_response: Matched entry DEFAULT at line 12 Mon Aug 17 09:43:12 2015 : Debug: (0) modsingle[accounting]: returned from attr_filter.accounting_response (rlm_attr_filter) for request 0 Mon Aug 17 09:43:12 2015 : Debug: (0) [attr_filter.accounting_response] = updated Mon Aug 17 09:43:12 2015 : Debug: (0) } # accounting = updated Mon Aug 17 09:43:12 2015 : Debug: (0) Empty pre-proxy section. Using default return values. Mon Aug 17 09:43:12 2015 : Debug: (0) proxy: Trying to allocate ID (0/2) Mon Aug 17 09:43:12 2015 : Debug: (0) proxy: Trying to open a new listener to the home server Mon Aug 17 09:43:12 2015 : Debug: Opening new proxy socket 'proxy address * port 0' Mon Aug 17 09:43:12 2015 : Debug: Listening on proxy address * port 36571 Mon Aug 17 09:43:12 2015 : Debug: (0) proxy: Trying to allocate ID (1/2) Mon Aug 17 09:43:12 2015 : Debug: (0) proxy: request is now in proxy hash Mon Aug 17 09:43:12 2015 : Debug: (0) proxy: allocating destination 127.0.0.1 port 60813 - Id 178 Mon Aug 17 09:43:12 2015 : Debug: (0) Proxying request to home server 127.0.0.1 port 60813 timeout 5.000000 01 0d 6d 6f 6e 2d 7a 64 72 6f 6a 65 31 04 06 d5 97 d8 c9 20 17 67 67 73 6e 2d 30 31 2d 62 62 31 2e 6f 72 61 6e 67 65 2e 73 6b 3d 06 00 00 00 05 28 06 00 00 00 01 1e 0c 70 72 6f 78 79 2e 63 6f 72 70 1f 0e 34 32 31 39 30 35 30 36 36 30 30 31 2c 12 64 35 39 37 64 39 31 35 32 33 39 32 30 38 34 30 32 12 64 35 39 37 64 39 31 35 31 31 63 32 38 30 32 34 33 06 00 00 00 01 08 06 ac 17 44 0b 06 06 00 00 00 02 07 06 00 00 00 07 2d 06 00 00 00 01 e2 06 00 00 00 08 e0 0a 32 01 91 04 60 09 98 f8 e3 0c 3c 44 35 3e 3c 39 37 3e d9 15 e1 06 23 92 08 40 e4 06 d5 97 fc 18 37 06 55 d1 90 90 21 04 39 34 Mon Aug 17 09:43:12 2015 : Debug: (0) Sent Accounting-Request Id 178 from 0.0.0.0:36571 to 127.0.0.1:60813 length 216 Mon Aug 17 09:43:12 2015 : Debug: (0) User-Name = "mon-zdroje1" Mon Aug 17 09:43:12 2015 : Debug: (0) NAS-IP-Address = 213.151.216.201 Mon Aug 17 09:43:12 2015 : Debug: (0) NAS-Identifier = " ggsn-01-bb1.orange.sk" Mon Aug 17 09:43:12 2015 : Debug: (0) NAS-Port-Type = Virtual Mon Aug 17 09:43:12 2015 : Debug: (0) Acct-Status-Type = Start Mon Aug 17 09:43:12 2015 : Debug: (0) Called-Station-Id = "proxy.corp" Mon Aug 17 09:43:12 2015 : Debug: (0) Calling-Station-Id = "421905066001" Mon Aug 17 09:43:12 2015 : Debug: (0) Acct-Session-Id = "d597d91523920840" Mon Aug 17 09:43:12 2015 : Debug: (0) Acct-Multi-Session-Id = "d597d91511c28024" Mon Aug 17 09:43:12 2015 : Debug: (0) Acct-Link-Count = 1 Mon Aug 17 09:43:12 2015 : Debug: (0) Framed-IP-Address = 172.23.68.11 Mon Aug 17 09:43:12 2015 : Debug: (0) Service-Type = Framed-User Mon Aug 17 09:43:12 2015 : Debug: (0) Framed-Protocol = GPRS-PDP-Context Mon Aug 17 09:43:12 2015 : Debug: (0) Acct-Authentic = RADIUS Mon Aug 17 09:43:12 2015 : Debug: (0) X-Ascend-PRI-Number-Type = 8 Mon Aug 17 09:43:12 2015 : Debug: (0) Attr-224 = 0x32019104600998f8 Mon Aug 17 09:43:12 2015 : Debug: (0) X-Ascend-Dial-Number = "<D5><97>\331\025" Mon Aug 17 09:43:12 2015 : Debug: (0) X-Ascend-Metric = 596772928 Mon Aug 17 09:43:12 2015 : Debug: (0) X-Ascend-Route-IP = 3583507480 Mon Aug 17 09:43:12 2015 : Debug: (0) Event-Timestamp = "Aug 17 2015 09:43:12 CEST" Mon Aug 17 09:43:12 2015 : Debug: (0) Proxy-State = 0x3934 Socket: 9 Proto: 17 Src IP: 0.0.0.0 port: 36571 Dst IP: 127.0.0.1 port: 60813 Code: 4 Id: 178 Length: 216 Vector: e74bb5b5237ba0490154d63d7a44838d Data: 01 0d 6d 6f 6e 2d 7a 64 72 6f 6a 65 31 04 06 d5 97 d8 c9 20 17 67 67 73 6e 2d 30 31 2d 62 62 31 2e 6f 72 61 6e 67 65 2e 73 6b 3d 06 00 00 00 05 28 06 00 00 00 01 1e 0c 70 72 6f 78 79 2e 63 6f 72 70 1f 0e 34 32 31 39 30 35 30 36 36 30 30 31 2c 12 64 35 39 37 64 39 31 35 32 33 39 32 30 38 34 30 32 12 64 35 39 37 64 39 31 35 31 31 63 32 38 30 32 34 33 06 00 00 00 01 08 06 ac 17 44 0b 06 06 00 00 00 02 07 06 00 00 00 07 2d 06 00 00 00 01 e2 06 00 00 00 08 e0 0a 32 01 91 04 60 09 98 f8 e3 0c 3c 44 35 3e 3c 39 37 3e d9 15 e1 06 23 92 08 40 e4 06 d5 97 fc 18 37 06 55 d1 90 90 21 04 39 34 Mon Aug 17 09:43:12 2015 : Debug: Waking up in 0.3 seconds. Mon Aug 17 09:43:12 2015 : Debug: (0) Expecting proxy response no later than 4.669935 seconds from now Mon Aug 17 09:43:12 2015 : Debug: Waking up in 4.6 seconds. Mon Aug 17 09:43:17 2015 : Debug: (0) No proxy response, giving up on request and marking it done Mon Aug 17 09:43:17 2015 : Proxy: Marking home server 127.0.0.1 port 60813 as zombie (it has not responded in 5.000000 seconds). Mon Aug 17 09:43:17 2015 : Debug: (1) proxy: Trying to allocate ID (0/2) Mon Aug 17 09:43:17 2015 : Debug: (1) proxy: request is now in proxy hash Mon Aug 17 09:43:17 2015 : Debug: (1) proxy: allocating destination 127.0.0.1 port 60813 - Id 18 Mon Aug 17 09:43:17 2015 : Debug: PING: Waiting 4 seconds for response to ping Mon Aug 17 09:43:17 2015 : Debug: (1) Sent Status-Server Id 18 from 0.0.0.0:36571 to 127.0.0.1:60813 length 0 Mon Aug 17 09:43:17 2015 : Debug: (1) Message-Authenticator := 0x00 Mon Aug 17 09:43:17 2015 : Debug: (1) NAS-Identifier := "Status Check 0. Are you alive?" 50 12 ... 20 20 53 74 61 74 75 73 20 43 68 65 63 6b 20 30 2e 20 41 72 65 20 79 6f 75 20 61 6c 69 76 65 3f Socket: 9 Proto: 0 Src IP: 0.0.0.0 port: 36571 Dst IP: 127.0.0.1 port: 60813 Code: 12 Id: 18 Length: 70 Vector: b4d8e37ec22a79bbb564a512370cfe23 Data: 50 12 f2 95 eb a2 33 84 d7 05 6c aa 0e fc d8 70 ce 4f 20 20 53 74 61 74 75 73 20 43 68 65 63 6b 20 30 2e 20 41 72 65 20 79 6f 75 20 61 6c 69 76 65 3f Mon Aug 17 09:43:17 2015 : Debug: PING: Next status packet in 30 seconds Mon Aug 17 09:43:17 2015 : ERROR: (0) Failing proxied request for user "mon-zdroje1", due to lack of any response from home server 127.0.0.1 port 60813 Mon Aug 17 09:43:17 2015 : Debug: (0) Clearing existing &reply: attributes Mon Aug 17 09:43:17 2015 : Debug: (0) Found Post-Proxy-Type Fail-Accounting Mon Aug 17 09:43:17 2015 : Debug: (0) proxy: request is no longer in proxy hash Mon Aug 17 09:43:17 2015 : Debug: (0) Post-Proxy-Type sub-section not found. Ignoring. Mon Aug 17 09:43:17 2015 : Debug: (0) Not sending reply to client. Mon Aug 17 09:43:17 2015 : Debug: (0) Finished request Mon Aug 17 09:43:17 2015 : Debug: (0) <done>: Cleaning up request packet ID 94 with timestamp +3 Mon Aug 17 09:43:17 2015 : Debug: Waking up in 3.9 seconds. Mon Aug 17 09:43:21 2015 : Error: No response to status check 1 ID 18 for home server 127.0.0.1 port 60813 Mon Aug 17 09:43:21 2015 : Debug: (1) proxy: request is no longer in proxy hash Mon Aug 17 09:43:21 2015 : Debug: Waking up in 24.4 seconds. Mon Aug 17 09:43:46 2015 : Debug: (2) proxy: Trying to allocate ID (0/2) Mon Aug 17 09:43:46 2015 : Debug: (2) proxy: request is now in proxy hash Mon Aug 17 09:43:46 2015 : Debug: (2) proxy: allocating destination 127.0.0.1 port 60813 - Id 14 Mon Aug 17 09:43:46 2015 : Debug: PING: Waiting 4 seconds for response to ping Mon Aug 17 09:43:46 2015 : Debug: (2) Sent Status-Server Id 14 from 0.0.0.0:36571 to 127.0.0.1:60813 length 0 Mon Aug 17 09:43:46 2015 : Debug: (2) Message-Authenticator := 0x00 Mon Aug 17 09:43:46 2015 : Debug: (2) NAS-Identifier := "Status Check 1. Are you alive?" 50 12 ... 20 20 53 74 61 74 75 73 20 43 68 65 63 6b 20 31 2e 20 41 72 65 20 79 6f 75 20 61 6c 69 76 65 3f Socket: 9 Proto: 0 Src IP: 0.0.0.0 port: 36571 Dst IP: 127.0.0.1 port: 60813 Code: 12 Id: 14 Length: 70 Vector: e05c638156153316b44d2765df2dc725 Data: 50 12 46 03 4a 15 13 fb 56 93 22 9f c1 46 0c 18 66 cc 20 20 53 74 61 74 75 73 20 43 68 65 63 6b 20 31 2e 20 41 72 65 20 79 6f 75 20 61 6c 69 76 65 3f Mon Aug 17 09:43:46 2015 : Debug: PING: Next status packet in 30 seconds Mon Aug 17 09:43:46 2015 : Debug: Waking up in 3.9 seconds. Socket: 9 Proto: 0 Src IP: 127.0.0.1 port: 60813 Dst IP: 127.0.0.1 port: 36571 Code: 5 Id: 14 Length: 20 Vector: c7c21077ac5bc7ab2bb6b2ca152354ed Mon Aug 17 09:43:46 2015 : Proxy: No outstanding request was found for Accounting-Response packet from host 127.0.0.1 port 60813 - ID 14 Mon Aug 17 09:43:46 2015 : Debug: Waking up in 3.9 seconds. Mon Aug 17 09:43:50 2015 : Error: No response to status check 2 ID 14 for home server 127.0.0.1 port 60813 Mon Aug 17 09:43:50 2015 : Debug: (2) proxy: request is no longer in proxy hash Mon Aug 17 09:43:50 2015 : Debug: Waking up in 27.7 seconds. Debug output (3rd party instance): [radiusd@tdrad1 proxy-test-A]$ ./run-debug.sh Copyright (C) 1999-2015 The FreeRADIUS server project and contributors There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE You may redistribute copies of FreeRADIUS under the terms of the GNU General Public License For more information about these matters, see the file named COPYRIGHT Starting - reading configuration files ... including dictionary file /app/radius/freeradius-3.0.9/share/freeradius/dictionary including dictionary file /app/radius/freeradius-3.0.9/share/freeradius/dictionary.dhcp including dictionary file /app/radius/freeradius-3.0.9/share/freeradius/dictionary.vqp including dictionary file /app/radius/conf/proxy-test-A/dictionary including configuration file /app/radius/conf/proxy-test-A/radiusd.conf including configuration file /app/radius/conf/proxy-test-A/templates.conf including configuration file /app/radius/conf/proxy-test-A/proxy.conf including configuration file /app/radius/conf/proxy-test-A/clients.conf including files in directory /app/radius/conf/proxy-test-A/mods-enabled/ including configuration file /app/radius/conf/proxy-test-A/mods-enabled/files including configuration file /app/radius/conf/proxy-test-A/mods-enabled/expr including configuration file /app/radius/conf/proxy-test-A/mods-enabled/preprocess including configuration file /app/radius/conf/proxy-test-A/mods-enabled/chap including configuration file /app/radius/conf/proxy-test-A/mods-enabled/always including configuration file /app/radius/conf/proxy-test-A/mods-enabled/linelog including configuration file /app/radius/conf/proxy-test-A/mods-enabled/realm including configuration file /app/radius/conf/proxy-test-A/mods-enabled/pap including files in directory /app/radius/conf/proxy-test-A/policy-enabled/ including configuration file /app/radius/conf/proxy-test-A/policy-enabled/debug including configuration file /app/radius/conf/proxy-test-A/policy-enabled/huntgroup including configuration file /app/radius/conf/proxy-test-A/policy-enabled/lns including configuration file /app/radius/conf/proxy-test-A/policy-enabled/username including configuration file /app/radius/conf/proxy-test-A/policy-enabled/nas including configuration file /app/radius/conf/proxy-test-A/policy-enabled/bdsl including configuration file /app/radius/conf/proxy-test-A/policy-enabled/SkyToll including configuration file /app/radius/conf/proxy-test-A/policy-enabled/filter including files in directory /app/radius/conf/proxy-test-A/sites-enabled/ including configuration file /app/radius/conf/proxy-test-A/sites-enabled/default main { name = "proxy-test-A" prefix = "/app/radius/freeradius-3.0.9" localstatedir = "/app_log/radius/proxy-test-A/" sbindir = "/app/radius/freeradius-3.0.9/sbin" logdir = "/app_log/radius/proxy-test-A/" run_dir = "/app_log/radius/proxy-test-A/" libdir = "/app/radius/freeradius-3.0.9/lib" radacctdir = "/app_log/radius/proxy-test-A//radacct" panic_action = "gdb -silent -x /app/radius/freeradius-3.0.9/../raddb/proxy-test-A/panic.gdb %e %p 2>&1 | tee /app_log/radius/proxy-test-A//gdb-proxy-test-A-%p.log" hostname_lookups = no max_request_time = 5 cleanup_delay = 2 max_requests = 25600 pidfile = "/app_log/radius/proxy-test-A//radius.pid" checkrad = "/app/radius/freeradius-3.0.9/sbin/checkrad" debug_level = 0 proxy_requests = yes log { stripped_names = no auth = no auth_badpass = no auth_goodpass = no colourise = yes msg_denied = "You are already logged in - access denied" } resources { } security { max_attributes = 200 reject_delay = 0.000000 status_server = yes allow_vulnerable_openssl = "yes" } } radiusd: #### Loading Realms and Home Servers #### proxy server { retry_delay = 5 retry_count = 3 default_fallback = no dead_time = 120 wake_all_if_all_dead = no } realm LOCAL { authhost = LOCAL accthost = LOCAL } realm NULL { authhost = LOCAL accthost = LOCAL } realm DEFAULT { authhost = LOCAL accthost = LOCAL } radiusd: #### Loading Clients #### client localhost { ipaddr = 127.0.0.1 require_message_authenticator = no secret = <<< secret >>> nas_type = "other" proto = "*" limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } Debugger not attached radiusd: #### Instantiating modules #### # Loaded module rlm_files # Loading module "files" from file /app/radius/conf/proxy-test-A/mods-enabled/files files { filename = "/app/radius/conf/proxy-test-A/mods-config/files/authorize" usersfile = "/app/radius/conf/proxy-test-A/mods-config/files/authorize" acctusersfile = "/app/radius/conf/proxy-test-A/mods-config/files/accounting" preproxy_usersfile = "/app/radius/conf/proxy-test-A/mods-config/files/pre-proxy" } # Loaded module rlm_expr # Loading module "expr" from file /app/radius/conf/proxy-test-A/mods-enabled/expr expr { safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /��������������������������������������a����������������������������������������" } # Loaded module rlm_preprocess # Loading module "preprocess" from file /app/radius/conf/proxy-test-A/mods-enabled/preprocess preprocess { with_ascend_hack = no ascend_channels_per_line = 23 with_ntdomain_hack = no with_specialix_jetstream_hack = no with_cisco_vsa_hack = no with_alvarion_vsa_hack = no } # Loaded module rlm_chap # Loading module "chap" from file /app/radius/conf/proxy-test-A/mods-enabled/chap # Loaded module rlm_always # Loading module "reject" from file /app/radius/conf/proxy-test-A/mods-enabled/always always reject { rcode = "reject" simulcount = 0 mpp = no } # Loading module "fail" from file /app/radius/conf/proxy-test-A/mods-enabled/always always fail { rcode = "fail" simulcount = 0 mpp = no } # Loading module "ok" from file /app/radius/conf/proxy-test-A/mods-enabled/always always ok { rcode = "ok" simulcount = 0 mpp = no } # Loading module "handled" from file /app/radius/conf/proxy-test-A/mods-enabled/always always handled { rcode = "handled" simulcount = 0 mpp = no } # Loading module "invalid" from file /app/radius/conf/proxy-test-A/mods-enabled/always always invalid { rcode = "invalid" simulcount = 0 mpp = no } # Loading module "userlock" from file /app/radius/conf/proxy-test-A/mods-enabled/always always userlock { rcode = "userlock" simulcount = 0 mpp = no } # Loading module "notfound" from file /app/radius/conf/proxy-test-A/mods-enabled/always always notfound { rcode = "notfound" simulcount = 0 mpp = no } # Loading module "noop" from file /app/radius/conf/proxy-test-A/mods-enabled/always always noop { rcode = "noop" simulcount = 0 mpp = no } # Loading module "updated" from file /app/radius/conf/proxy-test-A/mods-enabled/always always updated { rcode = "updated" simulcount = 0 mpp = no } # Loaded module rlm_linelog # Loading module "linelog" from file /app/radius/conf/proxy-test-A/mods-enabled/linelog linelog { filename = "/app_log/radius/proxy-test-A//linelog" escape_filenames = no syslog_severity = "info" permissions = 384 format = "This is a log message for %{User-Name}" reference = "messages.%{%{Packet-Type}:-default}" } # Loading module "log_request" from file /app/radius/conf/proxy-test-A/mods-enabled/linelog linelog log_request { filename = "/app_log/radius/proxy-test-A/radius.log" escape_filenames = no syslog_severity = "info" permissions = 384 format = "%t : Info: REQUEST(%{User-Name}): %{pairs:request:}" } # Loading module "log_control" from file /app/radius/conf/proxy-test-A/mods-enabled/linelog linelog log_control { filename = "/app_log/radius/proxy-test-A/radius.log" escape_filenames = no syslog_severity = "info" permissions = 384 format = "%t : Info: CONTROL(%{User-Name}): %{pairs:control:}" } # Loading module "log_reply" from file /app/radius/conf/proxy-test-A/mods-enabled/linelog linelog log_reply { filename = "/app_log/radius/proxy-test-A/radius.log" escape_filenames = no syslog_severity = "info" permissions = 384 format = "%t : Info REPLY(%{User-Name}): %{pairs:reply:}" } # Loaded module rlm_realm # Loading module "suffix" from file /app/radius/conf/proxy-test-A/mods-enabled/realm realm suffix { format = "suffix" delimiter = "@" ignore_default = no ignore_null = no } # Loaded module rlm_pap # Loading module "pap" from file /app/radius/conf/proxy-test-A/mods-enabled/pap pap { normalise = yes } instantiate { } modules { # Instantiating module "files" from file /app/radius/conf/proxy-test-A/mods-enabled/files reading pairlist file /app/radius/conf/proxy-test-A/mods-config/files/authorize reading pairlist file /app/radius/conf/proxy-test-A/mods-config/files/authorize reading pairlist file /app/radius/conf/proxy-test-A/mods-config/files/accounting reading pairlist file /app/radius/conf/proxy-test-A/mods-config/files/pre-proxy # Instantiating module "preprocess" from file /app/radius/conf/proxy-test-A/mods-enabled/preprocess # Instantiating module "reject" from file /app/radius/conf/proxy-test-A/mods-enabled/always # Instantiating module "fail" from file /app/radius/conf/proxy-test-A/mods-enabled/always # Instantiating module "ok" from file /app/radius/conf/proxy-test-A/mods-enabled/always # Instantiating module "handled" from file /app/radius/conf/proxy-test-A/mods-enabled/always # Instantiating module "invalid" from file /app/radius/conf/proxy-test-A/mods-enabled/always # Instantiating module "userlock" from file /app/radius/conf/proxy-test-A/mods-enabled/always # Instantiating module "notfound" from file /app/radius/conf/proxy-test-A/mods-enabled/always # Instantiating module "noop" from file /app/radius/conf/proxy-test-A/mods-enabled/always # Instantiating module "updated" from file /app/radius/conf/proxy-test-A/mods-enabled/always # Instantiating module "linelog" from file /app/radius/conf/proxy-test-A/mods-enabled/linelog # Instantiating module "log_request" from file /app/radius/conf/proxy-test-A/mods-enabled/linelog # Instantiating module "log_control" from file /app/radius/conf/proxy-test-A/mods-enabled/linelog # Instantiating module "log_reply" from file /app/radius/conf/proxy-test-A/mods-enabled/linelog # Instantiating module "suffix" from file /app/radius/conf/proxy-test-A/mods-enabled/realm # Instantiating module "pap" from file /app/radius/conf/proxy-test-A/mods-enabled/pap } # modules radiusd: #### Loading Virtual Servers #### server { # from file /app/radius/conf/proxy-test-A/radiusd.conf } # server server default { # from file /app/radius/conf/proxy-test-A/sites-enabled/default # Loading authenticate {...} # Loading authorize {...} # Loading accounting {...} } # server default radiusd: #### Opening IP addresses and Ports #### listen { type = "auth" ipv4addr = localhost IPv4 address [127.0.0.1] port = 60812 } listen { type = "acct" ipv4addr = localhost IPv4 address [127.0.0.1] port = 60813 } Listening on auth address 127.0.0.1 port 60812 bound to server default Listening on acct address 127.0.0.1 port 60813 bound to server default Ready to process requests (0) Received Status-Server Id 14 from 127.0.0.1:36571 to 127.0.0.1:60813 length 70 (0) Message-Authenticator = 0x46034a1513fb5693229fc1460c1866cc (0) NAS-Identifier = "Status Check 1. Are you alive?" (0) Sent Accounting-Response Id 14 from 127.0.0.1:60813 to 127.0.0.1:36571 length 0 (0) Finished request Waking up in 1.9 seconds. (0) <done>: Cleaning up request packet ID 14 with timestamp +23 Ready to process requests On Fri, Aug 14, 2015 at 10:11 PM, Alan DeKok <aland@deployingradius.com> wrote:
OK... that's just weird.
What are you doing with the config? You're clearly in some unusual corner case which causes this problem. I can't see it here, and there have been no other reports.
So... it works 99% of the time. What causes the problem?
i.e. start with a default config, test that it works. Make one change to get it closer to your current config, test it again, etc. When it stops working, you've narrowed it down to the one change that causes the problem.
You don't need to change much... just anything related to proxying and status checks. There's no need to look users up in a DB, etc.
Unless I know what's different about your system, it will be impossible to understand what's going wrong. And therefore impossible to fix it.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Thank you very much for help. I can confirm, that it works also for me :). On Mon, Aug 17, 2015 at 10:48 AM, Alan DeKok <aland@deployingradius.com> wrote:
On Aug 17, 2015, at 9:48 AM, Peter Balsianok <balsianok.peter@gmail.com> wrote:
Thank you for your advise Alan.
I have changed DEFAULT configuration, but the problem is persisting :(.
OK, I've managed to reproduce it here, and I've pushed changes which fix it for me.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
[radiusd@tdrad1 acct-test]$ ./run-debug.sh Copyright (C) 1999-2015 The FreeRADIUS server project and contributors There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE You may redistribute copies of FreeRADIUS under the terms of the GNU General Public License For more information about these matters, see the file named COPYRIGHT Starting - reading configuration files ... including dictionary file /app/radius/freeradius-3.0.9/share/freeradius/dictionary including dictionary file /app/radius/freeradius-3.0.9/share/freeradius/dictionary.dhcp including dictionary file /app/radius/freeradius-3.0.9/share/freeradius/dictionary.vqp including dictionary file /app/radius/conf/acct-test/dictionary including configuration file /app/radius/conf/acct-test/radiusd.conf including configuration file /app/radius/conf/acct-test/templates.conf including configuration file /app/radius/conf/acct-test/proxy.conf including configuration file /app/radius/conf/acct-test/clients.conf including files in directory /app/radius/conf/acct-test/mods-enabled/ including configuration file /app/radius/conf/acct-test/mods-enabled/unpack including configuration file /app/radius/conf/acct-test/mods-enabled/files including configuration file /app/radius/conf/acct-test/mods-enabled/expr including configuration file /app/radius/conf/acct-test/mods-enabled/preprocess including configuration file /app/radius/conf/acct-test/mods-enabled/attr_filter including configuration file /app/radius/conf/acct-test/mods-enabled/always including configuration file /app/radius/conf/acct-test/mods-enabled/linelog including configuration file /app/radius/conf/acct-test/mods-enabled/perl including configuration file /app/radius/conf/acct-test/mods-enabled/linelog-special including configuration file /app/radius/conf/acct-test/mods-enabled/realm including files in directory /app/radius/conf/acct-test/policy-enabled/ including configuration file /app/radius/conf/acct-test/policy-enabled/accounting including configuration file /app/radius/conf/acct-test/policy-enabled/huntgroup including configuration file /app/radius/conf/acct-test/policy-enabled/username including configuration file /app/radius/conf/acct-test/policy-enabled/nas including files in directory /app/radius/conf/acct-test/sites-enabled/ including configuration file /app/radius/conf/acct-test/sites-enabled/control-socket including configuration file /app/radius/conf/acct-test/sites-enabled/default main { name = "acct" prefix = "/app/radius/freeradius-3.0.9" localstatedir = "/app_log/radius/acct/" sbindir = "/app/radius/freeradius-3.0.9/sbin" logdir = "/app_log/radius/acct/" run_dir = "/app_log/radius/acct/" libdir = "/app/radius/freeradius-3.0.9/lib" radacctdir = "/app_log/radius/acct//radacct" panic_action = "gdb -silent -x /app/radius/freeradius-3.0.9/../raddb/acct/panic.gdb %e %p 2>&1 | tee /app_log/radius/acct//gdb-acct-%p.log" hostname_lookups = no max_request_time = 5 cleanup_delay = 2 max_requests = 25600 pidfile = "/app_log/radius/acct//radius.pid" checkrad = "/app/radius/freeradius-3.0.9/sbin/checkrad" debug_level = 0 proxy_requests = yes log { stripped_names = no auth = no auth_badpass = no auth_goodpass = no colourise = yes msg_denied = "You are already logged in - access denied" } resources { } security { max_attributes = 200 reject_delay = 0.000000 status_server = yes allow_vulnerable_openssl = "yes" } } radiusd: #### Loading Realms and Home Servers #### proxy server { retry_delay = 5 retry_count = 3 default_fallback = no dead_time = 120 wake_all_if_all_dead = no } WARNING: Ignoring "response_window = 30.000000", forcing to "response_window = 5.000000" home_server proxy_server_A { ipaddr = localhost IPv4 address [127.0.0.1] port = 60812 type = "auth+acct" secret = <<< secret >>> response_window = 30.000000 response_timeouts = 1 max_outstanding = 65536 zombie_period = 40 status_check = "request" ping_interval = 30 check_interval = 6 check_timeout = 4 num_answers_to_alive = 3 revive_interval = 300 username = "orange-system" password = "incorrect" limit { max_connections = 16 max_requests = 0 lifetime = 0 idle_timeout = 0 } coa { irt = 2 mrt = 16 mrc = 5 mrd = 30 } } WARNING: Ignoring "response_window = 30.000000", forcing to "response_window = 5.000000" home_server proxy_server_B { ipaddr = localhost IPv4 address [127.0.0.1] port = 61812 type = "auth+acct" secret = <<< secret >>> response_window = 30.000000 response_timeouts = 1 max_outstanding = 65536 zombie_period = 40 status_check = "request" ping_interval = 30 check_interval = 6 check_timeout = 4 num_answers_to_alive = 3 revive_interval = 300 username = "orange-system" password = "incorrect" limit { max_connections = 16 max_requests = 0 lifetime = 0 idle_timeout = 0 } coa { irt = 2 mrt = 16 mrc = 5 mrd = 30 } } home_server_pool proxy_pool { type = load-balance home_server = proxy_server_A home_server = proxy_server_B } home_server_pool proxy_pool { type = load-balance home_server = proxy_server_A home_server = proxy_server_B } realm testproxy.sk { auth_pool = proxy_pool acct_pool = proxy_pool nostrip } realm LOCAL { authhost = LOCAL accthost = LOCAL } realm NULL { authhost = LOCAL accthost = LOCAL } realm DEFAULT { authhost = LOCAL accthost = LOCAL } radiusd: #### Loading Clients #### client localhost { ipaddr = 127.0.0.1 require_message_authenticator = no secret = <<< secret >>> nas_type = "other" proto = "*" limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } Debugger not attached radiusd: #### Instantiating modules #### # Loaded module rlm_unpack # Loading module "unpack" from file /app/radius/conf/acct-test/mods-enabled/unpack # Loaded module rlm_files # Loading module "files" from file /app/radius/conf/acct-test/mods-enabled/files files { filename = "/app/radius/conf/acct-test/mods-config/files/authorize" usersfile = "/app/radius/conf/acct-test/mods-config/files/authorize" acctusersfile = "/app/radius/conf/acct-test/mods-config/files/accounting" preproxy_usersfile = "/app/radius/conf/acct-test/mods-config/files/pre-proxy" } # Loaded module rlm_expr # Loading module "expr" from file /app/radius/conf/acct-test/mods-enabled/expr expr { safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /äéöüàâæçèéêëîïôœùûüaÿÄÉÖÜßÀÂÆÇÈÉÊËÎÏÔŒÙÛÜŸ" } # Loaded module rlm_preprocess # Loading module "preprocess" from file /app/radius/conf/acct-test/mods-enabled/preprocess preprocess { with_ascend_hack = no ascend_channels_per_line = 23 with_ntdomain_hack = no with_specialix_jetstream_hack = no with_cisco_vsa_hack = no with_alvarion_vsa_hack = no } # Loaded module rlm_attr_filter # Loading module "attr_filter.post-proxy" from file /app/radius/conf/acct-test/mods-enabled/attr_filter attr_filter attr_filter.post-proxy { filename = "/app/radius/conf/acct-test/mods-config/attr_filter/post-proxy" key = "%{Realm}" relaxed = no } # Loading module "attr_filter.pre-proxy" from file /app/radius/conf/acct-test/mods-enabled/attr_filter attr_filter attr_filter.pre-proxy { filename = "/app/radius/conf/acct-test/mods-config/attr_filter/pre-proxy" key = "%{Realm}" relaxed = no } # Loading module "attr_filter.access_reject" from file /app/radius/conf/acct-test/mods-enabled/attr_filter attr_filter attr_filter.access_reject { filename = "/app/radius/conf/acct-test/mods-config/attr_filter/access_reject" key = "%{User-Name}" relaxed = no } # Loading module "attr_filter.access_challenge" from file /app/radius/conf/acct-test/mods-enabled/attr_filter attr_filter attr_filter.access_challenge { filename = "/app/radius/conf/acct-test/mods-config/attr_filter/access_challenge" key = "%{User-Name}" relaxed = no } # Loading module "attr_filter.accounting_response" from file /app/radius/conf/acct-test/mods-enabled/attr_filter attr_filter attr_filter.accounting_response { filename = "/app/radius/conf/acct-test/mods-config/attr_filter/accounting_response" key = "%{User-Name}" relaxed = no } # Loaded module rlm_always # Loading module "reject" from file /app/radius/conf/acct-test/mods-enabled/always always reject { rcode = "reject" simulcount = 0 mpp = no } # Loading module "fail" from file /app/radius/conf/acct-test/mods-enabled/always always fail { rcode = "fail" simulcount = 0 mpp = no } # Loading module "ok" from file /app/radius/conf/acct-test/mods-enabled/always always ok { rcode = "ok" simulcount = 0 mpp = no } # Loading module "handled" from file /app/radius/conf/acct-test/mods-enabled/always always handled { rcode = "handled" simulcount = 0 mpp = no } # Loading module "invalid" from file /app/radius/conf/acct-test/mods-enabled/always always invalid { rcode = "invalid" simulcount = 0 mpp = no } # Loading module "userlock" from file /app/radius/conf/acct-test/mods-enabled/always always userlock { rcode = "userlock" simulcount = 0 mpp = no } # Loading module "notfound" from file /app/radius/conf/acct-test/mods-enabled/always always notfound { rcode = "notfound" simulcount = 0 mpp = no } # Loading module "noop" from file /app/radius/conf/acct-test/mods-enabled/always always noop { rcode = "noop" simulcount = 0 mpp = no } # Loading module "updated" from file /app/radius/conf/acct-test/mods-enabled/always always updated { rcode = "updated" simulcount = 0 mpp = no } # Loaded module rlm_linelog # Loading module "linelog" from file /app/radius/conf/acct-test/mods-enabled/linelog linelog { filename = "/app_log/radius/acct//linelog" escape_filenames = no syslog_severity = "info" permissions = 384 format = "This is a log message for %{User-Name}" reference = "messages.%{%{Packet-Type}:-default}" } # Loading module "log_request" from file /app/radius/conf/acct-test/mods-enabled/linelog linelog log_request { filename = "/app_log/radius/acct//log.gen" escape_filenames = no syslog_severity = "info" permissions = 384 format = "%t : Info: REQUEST(%{User-Name}): %{pairs:request:}" } # Loading module "log_control" from file /app/radius/conf/acct-test/mods-enabled/linelog linelog log_control { filename = "/app_log/radius/acct//log.gen" escape_filenames = no syslog_severity = "info" permissions = 384 format = "%t : Info: CONTROL(%{User-Name}): %{pairs:control:}" } # Loading module "log_proxy_request" from file /app/radius/conf/acct-test/mods-enabled/linelog linelog log_proxy_request { filename = "/app_log/radius/acct//log.gen" escape_filenames = no syslog_severity = "info" permissions = 384 format = "%t : Info: PROXY-REQUEST(%{User-Name}): %{pairs:proxy-request:}" } # Loading module "log_reply" from file /app/radius/conf/acct-test/mods-enabled/linelog linelog log_reply { filename = "/app_log/radius/acct//log.gen" escape_filenames = no syslog_severity = "info" permissions = 384 format = "%t : Info REPLY(%{User-Name}): %{pairs:reply:}" } # Loading module "log_proxy_reply" from file /app/radius/conf/acct-test/mods-enabled/linelog linelog log_proxy_reply { filename = "/app_log/radius/acct//log.gen" escape_filenames = no syslog_severity = "info" permissions = 384 format = "%t : Info PROXY-REPLY(%{User-Name}): Packet-Type=%{proxy-reply:Packet-Type} %{pairs:proxy-reply:}" } # Loaded module rlm_perl # Loading module "perl" from file /app/radius/conf/acct-test/mods-enabled/perl perl { filename = "/app/radius/conf/acct-test/mods-config/perl/radius.pm" func_authorize = "authorize" func_authenticate = "authenticate" func_post_auth = "post_auth" func_accounting = "accounting" func_preacct = "preacct" func_checksimul = "checksimul" func_detach = "detach" func_xlat = "xlat" func_pre_proxy = "pre_proxy" func_post_proxy = "post_proxy" func_recv_coa = "recv_coa" func_send_coa = "send_coa" } # Loading module "log_acct_bras" from file /app/radius/conf/acct-test/mods-enabled/linelog-special linelog log_acct_bras { filename = "/app_log/radius/loaders/bdsl-%D.log" escape_filenames = no syslog_severity = "info" permissions = 384 format = "" reference = "Accounting-Request.%{%{Acct-Status-Type}:-unknown}" } # Loading module "log_acct_common" from file /app/radius/conf/acct-test/mods-enabled/linelog-special linelog log_acct_common { filename = "/app_log/radius/loaders/common-%D.log" escape_filenames = no syslog_severity = "info" permissions = 384 format = "" reference = "Accounting-Request.%{%{Acct-Status-Type}:-unknown}" } # Loading module "log_dispatch_bras" from file /app/radius/conf/acct-test/mods-enabled/linelog-special linelog log_dispatch_bras { filename = "/app_log/radius/notification/dispatcher-%D.log" escape_filenames = no syslog_severity = "info" permissions = 384 format = "00 %l (0)%{User-Name}|radiusNasPortId|%{NAS-IP-Address}|radiusClientIPAddress|%{%{Framed-IP-Address}:-Unknown}}" } # Loading module "log_dispatch_asa" from file /app/radius/conf/acct-test/mods-enabled/linelog-special linelog log_dispatch_asa { filename = "/app_log/radius/notification/dispatcher-%D.log" escape_filenames = no syslog_severity = "info" permissions = 384 format = "00 %l %{User-Name}|radiusNasPortId|%{NAS-IP-Address}|radiusClientIPAddress|%{%{Calling-Station-Id}:-Unknown}}|radiusTunnelClientEndpoint|%{%{Framed-IP-Address}:-Unknown}" } # Loaded module rlm_realm # Loading module "suffix" from file /app/radius/conf/acct-test/mods-enabled/realm realm suffix { format = "suffix" delimiter = "@" ignore_default = no ignore_null = no } instantiate { # Instantiating module "perl" from file /app/radius/conf/acct-test/mods-enabled/perl config { logdir = /app_log/radius/acct/ confdir = /app/radius/conf/acct-test/ name = acct } } modules { # Instantiating module "files" from file /app/radius/conf/acct-test/mods-enabled/files reading pairlist file /app/radius/conf/acct-test/mods-config/files/authorize reading pairlist file /app/radius/conf/acct-test/mods-config/files/authorize reading pairlist file /app/radius/conf/acct-test/mods-config/files/accounting reading pairlist file /app/radius/conf/acct-test/mods-config/files/pre-proxy # Instantiating module "preprocess" from file /app/radius/conf/acct-test/mods-enabled/preprocess # Instantiating module "attr_filter.post-proxy" from file /app/radius/conf/acct-test/mods-enabled/attr_filter reading pairlist file /app/radius/conf/acct-test/mods-config/attr_filter/post-proxy # Instantiating module "attr_filter.pre-proxy" from file /app/radius/conf/acct-test/mods-enabled/attr_filter reading pairlist file /app/radius/conf/acct-test/mods-config/attr_filter/pre-proxy # Instantiating module "attr_filter.access_reject" from file /app/radius/conf/acct-test/mods-enabled/attr_filter reading pairlist file /app/radius/conf/acct-test/mods-config/attr_filter/access_reject # Instantiating module "attr_filter.access_challenge" from file /app/radius/conf/acct-test/mods-enabled/attr_filter reading pairlist file /app/radius/conf/acct-test/mods-config/attr_filter/access_challenge # Instantiating module "attr_filter.accounting_response" from file /app/radius/conf/acct-test/mods-enabled/attr_filter reading pairlist file /app/radius/conf/acct-test/mods-config/attr_filter/accounting_response # Instantiating module "reject" from file /app/radius/conf/acct-test/mods-enabled/always # Instantiating module "fail" from file /app/radius/conf/acct-test/mods-enabled/always # Instantiating module "ok" from file /app/radius/conf/acct-test/mods-enabled/always # Instantiating module "handled" from file /app/radius/conf/acct-test/mods-enabled/always # Instantiating module "invalid" from file /app/radius/conf/acct-test/mods-enabled/always # Instantiating module "userlock" from file /app/radius/conf/acct-test/mods-enabled/always # Instantiating module "notfound" from file /app/radius/conf/acct-test/mods-enabled/always # Instantiating module "noop" from file /app/radius/conf/acct-test/mods-enabled/always # Instantiating module "updated" from file /app/radius/conf/acct-test/mods-enabled/always # Instantiating module "linelog" from file /app/radius/conf/acct-test/mods-enabled/linelog # Instantiating module "log_request" from file /app/radius/conf/acct-test/mods-enabled/linelog # Instantiating module "log_control" from file /app/radius/conf/acct-test/mods-enabled/linelog # Instantiating module "log_proxy_request" from file /app/radius/conf/acct-test/mods-enabled/linelog # Instantiating module "log_reply" from file /app/radius/conf/acct-test/mods-enabled/linelog # Instantiating module "log_proxy_reply" from file /app/radius/conf/acct-test/mods-enabled/linelog # Instantiating module "log_acct_bras" from file /app/radius/conf/acct-test/mods-enabled/linelog-special # Instantiating module "log_acct_common" from file /app/radius/conf/acct-test/mods-enabled/linelog-special # Instantiating module "log_dispatch_bras" from file /app/radius/conf/acct-test/mods-enabled/linelog-special # Instantiating module "log_dispatch_asa" from file /app/radius/conf/acct-test/mods-enabled/linelog-special # Instantiating module "suffix" from file /app/radius/conf/acct-test/mods-enabled/realm } # modules radiusd: #### Loading Virtual Servers #### server { # from file /app/radius/conf/acct-test/radiusd.conf } # server server default { # from file /app/radius/conf/acct-test/sites-enabled/default # Loading preacct {...} # Loading accounting {...} } # server default radiusd: #### Opening IP addresses and Ports #### listen { type = "control" listen { socket = "/app_log/radius/acct/control.socket" mode = "rw" peercred = yes } } listen { type = "acct" ipv4addr = * port = 10813 limit { max_pps = 0 max_connections = 16 lifetime = 0 idle_timeout = 30 } } listen { type = "acct" ipv4addr = * port = 10646 limit { max_pps = 0 max_connections = 16 lifetime = 0 idle_timeout = 30 } } Listening on command file /app_log/radius/acct/control.socket Listening on acct address * port 10813 bound to server default Listening on acct address * port 10646 bound to server default Opening new proxy socket 'proxy address * port 0' Listening on proxy address * port 47178 Ready to process requests ####### Both proxy servers are down, send request ###### (0) Received Accounting-Request Id 40 from 127.0.0.1:56107 to 127.0.0.1:10813 length 219 (0) User-Name = "mon-zdroje1@testproxy.sk" (0) NAS-IP-Address = 213.151.216.201 (0) NAS-Identifier = "ggsn-01-bb1.orange.sk" (0) NAS-Port-Type = Virtual (0) Acct-Status-Type = Start (0) Called-Station-Id = "proxy.corp" (0) Calling-Station-Id = "421905066001" (0) Acct-Session-Id = "d597d91523920840" (0) Acct-Multi-Session-Id = "d597d91511c28024" (0) Acct-Link-Count = 1 (0) Framed-IP-Address = 172.23.68.11 (0) Service-Type = Framed-User (0) Framed-Protocol = GPRS-PDP-Context (0) Acct-Authentic = RADIUS (0) X-Ascend-PRI-Number-Type = 8 (0) Attr-224 = 0x32019104600998f8 (0) X-Ascend-Dial-Number = "<D5><97>\331\025" (0) X-Ascend-Metric = 596772928 (0) X-Ascend-Route-IP = 213.151.252.24 (0) # Executing section preacct from file /app/radius/conf/acct-test/sites-enabled/default (0) preacct { (0) [preprocess] = ok (0) if ( ! &NAS-IP-Address ) { (0) if ( ! &NAS-IP-Address ) -> FALSE (0) else { (0) policy huntgroup { (0) switch &NAS-IP-Address { (0) case 213.151.216.201 { (0) update request { (0) &Huntgroup-Name := 'GGSN' (0) } # update request = noop (0) } # case 213.151.216.201 = noop (0) } # switch &NAS-IP-Address = noop (0) } # policy huntgroup = noop (0) } # else = noop (0) policy username { (0) if (!&User-Name || &User-Name == '') { (0) if (!&User-Name || &User-Name == '') -> FALSE (0) elsif (&User-Name =~ /^[0-9]+$/) { (0) elsif (&User-Name =~ /^[0-9]+$/) -> FALSE (0) } # policy username = ok (0) policy acct_counters64.preacct { (0) update request { (0) WARNING: Can't find &Acct-Input-Gigawords. Using 0 as operand value (0) WARNING: Can't find &Acct-Input-Octets. Using 0 as operand value (0) EXPAND %{expr:(&Acct-Input-Gigawords << 32) | &Acct-Input-Octets} (0) --> 0 (0) &Acct-Input-Octets64 = 0 (0) WARNING: Can't find &Acct-Output-Gigawords. Using 0 as operand value (0) WARNING: Can't find &Acct-Output-Octets. Using 0 as operand value (0) EXPAND %{expr:(&Acct-Output-Gigawords << 32) | &Acct-Output-Octets} (0) --> 0 (0) &Acct-Output-Octets64 = 0 (0) } # update request = noop (0) } # policy acct_counters64.preacct = noop (0) if (&Class) { (0) if (&Class) -> FALSE (0) policy acct_unique { (0) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) { (0) EXPAND %{string:Class} (0) --> (0) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) -> FALSE (0) else { (0) update request { (0) EXPAND %{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}} (0) --> 772f7c0824d05fe594797a68d34c3161 (0) &Acct-Unique-Session-Id := 772f7c0824d05fe594797a68d34c3161 (0) } # update request = noop (0) } # else = noop (0) } # policy acct_unique = noop (0) suffix: Checking for suffix after "@" (0) suffix: Looking up realm "testproxy.sk" for User-Name = " mon-zdroje1@testproxy.sk" (0) suffix: Found realm "testproxy.sk" (0) suffix: Adding Realm = "testproxy.sk" (0) suffix: Proxying request from user mon-zdroje1@testproxy.sk to realm testproxy.sk (0) suffix: Preparing to proxy accounting request to realm "testproxy.sk" (0) [suffix] = updated (0) log_control: EXPAND /app_log/radius/acct//log.gen (0) log_control: --> /app_log/radius/acct//log.gen (0) log_control: EXPAND %t : Info: CONTROL(%{User-Name}): %{pairs:control:} (0) log_control: --> Wed Aug 12 09:26:59 2015 : Info: CONTROL( mon-zdroje1@testproxy.sk): Proxy-To-Realm = "testproxy.sk" (0) [log_control] = ok (0) } # preacct = updated (0) # Executing section accounting from file /app/radius/conf/acct-test/sites-enabled/default (0) accounting { (0) if (&Huntgroup-Name == 'LNS') { (0) if (&Huntgroup-Name == 'LNS') -> FALSE (0) elsif (&Huntgroup-Name == 'BRAS') { (0) elsif (&Huntgroup-Name == 'BRAS') -> FALSE (0) elsif (&Called-Station-Id && &Called-Station-Id =~ /SkyToll/i) { (0) elsif (&Called-Station-Id && &Called-Station-Id =~ /SkyToll/i) -> FALSE (0) elsif (&Huntgroup-Name == 'ASA') { (0) elsif (&Huntgroup-Name == 'ASA') -> FALSE (0) else { (0) if (&control:Proxy-To-Realm ) { (0) if (&control:Proxy-To-Realm ) -> TRUE (0) (&control:Proxy-To-Realm ) { ... } # empty sub-section is ignored (0) ... skipping else for request 0: Preceding "if" was taken (0) } # else = noop (0) [ok] = ok (0) } # accounting = ok Opening new proxy socket 'proxy address * port 0' Listening on proxy address * port 57096 (0) Proxying request to home server 127.0.0.1 port 61813 timeout 5.000000 (0) Sent Accounting-Request Id 210 from 0.0.0.0:57096 to 127.0.0.1:61813 length 229 (0) User-Name = "mon-zdroje1@testproxy.sk" (0) NAS-IP-Address = 213.151.216.201 (0) NAS-Identifier = "ggsn-01-bb1.orange.sk" (0) NAS-Port-Type = Virtual (0) Acct-Status-Type = Start (0) Called-Station-Id = "proxy.corp" (0) Calling-Station-Id = "421905066001" (0) Acct-Session-Id = "d597d91523920840" (0) Acct-Multi-Session-Id = "d597d91511c28024" (0) Acct-Link-Count = 1 (0) Framed-IP-Address = 172.23.68.11 (0) Service-Type = Framed-User (0) Framed-Protocol = GPRS-PDP-Context (0) Acct-Authentic = RADIUS (0) X-Ascend-PRI-Number-Type = 8 (0) Attr-224 = 0x32019104600998f8 (0) X-Ascend-Dial-Number = "<D5><97>\331\025" (0) X-Ascend-Metric = 596772928 (0) X-Ascend-Route-IP = 213.151.252.24 (0) Event-Timestamp = "Aug 12 2015 09:26:59 CEST" (0) Proxy-State = 0x3430 Waking up in 0.3 seconds. (0) Expecting proxy response no later than 4.669045 seconds from now Waking up in 4.6 seconds. (0) No proxy response, giving up on request and marking it done Marking home server 127.0.0.1 port 61813 as zombie (it has not responded in 5.000000 seconds). PING: Waiting 4 seconds for response to ping PING: Next status packet in 6 seconds (0) ERROR: Failing proxied request for user "mon-zdroje1@testproxy.sk", due to lack of any response from home server 127.0.0.1 port 61813 (0) Clearing existing &reply: attributes (0) Found Post-Proxy-Type Fail-Accounting (0) Post-Proxy-Type sub-section not found. Ignoring. (0) Not sending reply to client. (0) Finished request (0) <done>: Cleaning up request packet ID 40 with timestamp +17 Waking up in 3.9 seconds. No response to status check 1 for home server 127.0.0.1 port 61813 Waking up in 2.4 seconds. PING: Waiting 4 seconds for response to ping PING: Next status packet in 6 seconds Waking up in 3.9 seconds. No response to status check 2 for home server 127.0.0.1 port 61813 Waking up in 1.7 seconds. PING: Waiting 4 seconds for response to ping PING: Next status packet in 6 seconds Waking up in 3.9 seconds. ###### Both severs are up ########### No outstanding request was found for reply from host 127.0.0.1 port 61813 - ID 91 Waking up in 3.9 seconds. No response to status check 3 for home server 127.0.0.1 port 61813 Waking up in 2.8 seconds. PING: Waiting 4 seconds for response to ping PING: Next status packet in 6 seconds Waking up in 3.9 seconds. No outstanding request was found for reply from host 127.0.0.1 port 61813 - ID 252 Waking up in 3.9 seconds. No response to status check 4 for home server 127.0.0.1 port 61813 Waking up in 1.4 seconds. Debug output from proxy server ( procy-test-B ): Ready to process requests (0) Received Accounting-Request Id 91 from 127.0.0.1:57096 to 127.0.0.1:61813 length 89 (0) User-Name = "orange-system" (0) Acct-Status-Type = Stop (0) Acct-Session-Id = "00000000" (0) Event-Timestamp = "Aug 12 2015 09:27:17 CEST" (0) NAS-Identifier = "Status Check 2. Are you alive?" (0) # Executing section accounting from file /app/radius/conf/proxy-test-B/sites-enabled/default (0) accounting { (0) [ok] = ok (0) } # accounting = ok (0) Sent Accounting-Response Id 91 from 127.0.0.1:61813 to 127.0.0.1:57096 length 0 (0) Finished request (0) <done>: Cleaning up request packet ID 91 with timestamp +3 Ready to process requests (1) Received Accounting-Request Id 252 from 127.0.0.1:57096 to 127.0.0.1:61813 length 89 (1) User-Name = "orange-system" (1) Acct-Status-Type = Stop (1) Acct-Session-Id = "00000000" (1) Event-Timestamp = "Aug 12 2015 09:27:23 CEST" (1) NAS-Identifier = "Status Check 3. Are you alive?" (1) # Executing section accounting from file /app/radius/conf/proxy-test-B/sites-enabled/default (1) accounting { (1) [ok] = ok (1) } # accounting = ok (1) Sent Accounting-Response Id 252 from 127.0.0.1:61813 to 127.0.0.1:57096 length 0 (1) Finished request (1) <done>: Cleaning up request packet ID 252 with timestamp +9 Ready to process requests On Tue, Aug 11, 2015 at 9:42 AM, Alan DeKok <aland@deployingradius.com> wrote:
On Aug 11, 2015, at 9:14 AM, Peter Balsianok <balsianok.peter@gmail.com> wrote:
Could you please tell me, why my RADIUS server doesnt find reply (status-check via using "request" ) from 3rd party RADIUS server ?
Post the debug output as suggested in the FAQ, "man" pages, web pages, and daily on this list.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Do a tcpdump on each system to verify the packets are leaving on the right interfaces and are being received on the original server (your logs show packet being received by the remote server and response being sent - so you need to see where that packet goes and that it is received by the original server) alan
Could you please tell me, why my >RADIUS server doesnt find reply (status-check via using "request" ) from >3rd party RADIUS server ?
Does that other server support status-server? What do the logs on that other server show? What does the debug on that other server show and what does the debug on your server show? alan
participants (4)
-
Alan Buxey -
Alan DeKok -
Arran Cudbard-Bell -
Peter Balsianok