RadSec Authentication + Accounting Issue
Donald Sherker
dsherker at gmail.com
Thu Mar 12 19:22:15 CET 2015
We are running FreeRADIUS 3.0.7 configured to send authentication and
accounting to another AAA server. With just auth configured this
works without a problem. When we configure it for both auth and
accounting, authentication will work until the first attempt to sent
an accounting packet. It does not appear that this packet is ever
sent, and any further communication with the remote AAA server does
not work. Our FreeRADIUS server has to be restarted to authenticate a
user again. The remote server portion of the tls file is :
home_server remote_server1 {
ipaddr = z.z.z.z
port = 2083
type = auth+acct
secret = radsec
proto = tcp
status_check = none
tls {
private_key_file = ${certdir}/cert.key
certificate_file = ${certdir}/cert.csrb64.cer
ca_file = /usr/local/etc/raddb/certs/cert.crt
dh_file = ${certdir}/dh
random_file = ${certdir}/random
fragment_size = 8192
ca_path = ${cadir}
cipher_list = "DEFAULT"
}
}
home_server_pool remote_server_pool {
type = client-balance
home_server = remote_server1
}
realm test_realm {
auth_pool = remote_server_pool
acct_pool = remote_server_pool
}
Let me know if any other configuration files would be useful.
Below is a portion of the logs when this happens:
(0) Received Access-Request Id 77 from x.x.x.x:50204 to y.y.y.y:1812 length 266
(0) User-Name = 'user at realm'
(0) NAS-IP-Address = x.x.x.x
(0) NAS-Identifier = 'NAS'
(0) Called-Station-Id = '000000000000:SSID'
(0) NAS-Port-Type = Wireless-802.11
(0) NAS-Port = 0
(0) Calling-Station-Id = '111111111111'
(0) Connect-Info = 'CONNECT 0Mbps 802.11b'
(0) Acct-Session-Id = '5501AFCF-00000020'
(0) Framed-MTU = 1400
(0) EAP-Message =
0x020f0038013033313032363039383235373236323240776c616e2e6d6e633236302e6d63633331302e336770706e6574776f726b2e6f7267
(0) Message-Authenticator = 0x02a8eda3497d667353ec8a96d14a2d8b
(0) # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default
(0) authorize {
(0) [preprocess] = ok
(0) [chap] = noop
(0) [mschap] = noop
(0) [digest] = noop
(0) suffix: Checking for suffix after "@"
(0) suffix: Looking up realm "realm" for User-Name = "user at realm"
(0) suffix: Found realm "realm"
(0) suffix: Adding Stripped-User-Name = "user"
(0) suffix: Adding Realm = "realm"
(0) suffix: Proxying request from user user to realm realm
(0) suffix: Preparing to proxy authentication request to realm "realm"
(0) [suffix] = updated
(0) eap: Request is supposed to be proxied to Realm realm. Not doing EAP.
(0) [eap] = noop
(0) [files] = noop
(0) [expiration] = noop
(0) [logintime] = noop
(0) } # authorize = updated
Opening new proxy socket 'proxy (0.0.0.0, 0) -> home_server (z.z.z.z, 2083)'
Trying SSL to port 2083
Requiring Server certificate
(0) (other): before/connect initialization
(0) TLS_connect: before/connect initialization
(0) >>> Unknown TLS version [length 00f0]
(0) TLS_connect: SSLv2/v3 write client hello A
Waking up in 0.4 seconds.
(0) <<< Unknown TLS version [length 0051]
(0) TLS_connect: SSLv3 read server hello A
(0) <<< Unknown TLS version [length 1612]
(0) TLS Verify adding attributes
(0) chain-depth=3,
(0) error=0
(0) TLS Verify adding attributes
(0) chain-depth=2,
(0) error=0
(0) TLS Verify adding attributes
(0) chain-depth=1,
(0) error=0
(0) TLS Verify adding attributes
(0) chain-depth=0,
(0) error=0
(0) TLS_connect: SSLv3 read server certificate A
(0) <<< Unknown TLS version [length 0004]
(0) TLS_connect: SSLv3 read server done A
(0) >>> Unknown TLS version [length 0106]
(0) TLS_connect: SSLv3 write client key exchange A
(0) >>> Unknown TLS version [length 0001]
(0) TLS_connect: SSLv3 write change cipher spec A
(0) >>> Unknown TLS version [length 0010]
(0) TLS_connect: SSLv3 write finished A
(0) TLS_connect: SSLv3 flush data
(0) <<< Unknown TLS version [length 0001]
(0) <<< Unknown TLS version [length 0010]
(0) TLS_connect: SSLv3 read finished A
(0) (other): SSL negotiation finished successfully
Listening on proxy (y.y.y.y, 38309) -> home_server (z.z.z.z, 2083)
(0) Proxying request to home server z.z.z.z port 2083 (TLS) timeout 30.000000
(0) Sent Access-Request Id 154 from y.y.y.y:38309 to z.z.z.z:2083 length 241
(0) User-Name = 'user'
(0) NAS-IP-Address = x.x.x.x
(0) NAS-Identifier = 'NAS'
(0) Called-Station-Id = '000000000000:SSID'
(0) NAS-Port-Type = Wireless-802.11
(0) NAS-Port = 0
(0) Calling-Station-Id = '111111111111'
(0) Connect-Info = 'CONNECT 0Mbps 802.11b'
(0) Acct-Session-Id = '5501AFCF-00000020'
(0) Framed-MTU = 1400
(0) EAP-Message =
0x020f0038013033313032363039383235373236323240776c616e2e6d6e633236302e6d63633331302e336770706e6574776f726b2e6f7267
(0) Message-Authenticator = 0x02a8eda3497d667353ec8a96d14a2d8b
(0) Event-Timestamp = 'Mar 12 2015 12:32:11 EDT'
(0) Proxy-State = 0x3737
Thread 4 waiting to be assigned a request
Waking up in 0.6 seconds.
Waking up in 0.3 seconds.
Thread 5 got semaphore
Thread 5 handling request 0, (1 handled so far)
(0) Clearing existing &reply: attributes
(0) Received Access-Challenge Id 154 from z.z.z.z:2083 to
y.y.y.y:38309 length 146
(0) EAP-Message =
0x011000441701000001050000cf2b3cef0a31f39b5014b7d4aa1f06c302050000610ede3617be0000d98e7d329d6162a20b050000bbc85cccebdcb3322314a4edf8a166e3
(0) Message-Authenticator = 0x68def4c1076bd78e494481bf9526bc66
(0) State = 0xffabd5a1e2e5fc51254946eda3439a4f92703fe4a5ecd73b05bfad82ee821f95
(0) Proxy-State = 0x3737
(0) # Executing section post-proxy from file
/usr/local/etc/raddb/sites-enabled/default
(0) post-proxy {
(0) eap: No pre-existing handler found
(0) [eap] = noop
(0) } # post-proxy = noop
(0) Using Post-Auth-Type Challenge
(0) Post-Auth-Type sub-section not found. Ignoring.
(0) # Executing group from file /usr/local/etc/raddb/sites-enabled/default
(0) Sent Access-Challenge Id 77 from y.y.y.y:1812 to x.x.x.x:50204 length 142
(0) EAP-Message =
0x011000441701000001050000cf2b3cef0a31f39b5014b7d4aa1f06c302050000610ede3617be0000d98e7d329d6162a20b050000bbc85cccebdcb3322314a4edf8a166e3
(0) Message-Authenticator = 0x68def4c1076bd78e494481bf9526bc66
(0) State = 0xffabd5a1e2e5fc51254946eda3439a4f92703fe4a5ecd73b05bfad82ee821f95
(0) Finished request
Thread 5 waiting to be assigned a request
Waking up in 4.6 seconds.
Waking up in 0.3 seconds.
Thread 2 got semaphore
Thread 2 handling request 1, (1 handled so far)
(1) Received Access-Request Id 78 from x.x.x.x:50204 to y.y.y.y:1812 length 288
(1) User-Name = 'user at realm'
(1) NAS-IP-Address = x.x.x.x
(1) NAS-Identifier = 'NAS'
(1) Called-Station-Id = '000000000000:SSID'
(1) NAS-Port-Type = Wireless-802.11
(1) NAS-Port = 0
(1) Calling-Station-Id = '111111111111'
(1) Connect-Info = 'CONNECT 0Mbps 802.11b'
(1) Acct-Session-Id = '5501AFCF-00000020'
(1) Framed-MTU = 1400
(1) EAP-Message =
0x0210002c17010000030300406e414a35103ee4e0860100000b050000f27bc26235ef1b663594aadd343a6ab4
(1) State = 0xffabd5a1e2e5fc51254946eda3439a4f92703fe4a5ecd73b05bfad82ee821f95
(1) Message-Authenticator = 0xfc792a3aae3b5a6322f357a3821bc0f2
(1) session-state: No cached attributes
(1) # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default
(1) authorize {
(1) [preprocess] = ok
(1) [chap] = noop
(1) [mschap] = noop
(1) [digest] = noop
(1) suffix: Checking for suffix after "@"
(1) suffix: Looking up realm "realm" for User-Name = "user at realm"
(1) suffix: Found realm "realm"
(1) suffix: Adding Stripped-User-Name = "user"
(1) suffix: Adding Realm = "realm"
(1) suffix: Proxying request from user user to realm realm
(1) suffix: Preparing to proxy authentication request to realm "realm"
(1) [suffix] = updated
(1) eap: Request is supposed to be proxied to Realm realm. Not doing EAP.
(1) [eap] = noop
(1) [files] = noop
(1) [expiration] = noop
(1) [logintime] = noop
(1) } # authorize = updated
(1) Proxying request to home server z.z.z.z port 2083 (TLS) timeout 30.000000
(1) Sent Access-Request Id 160 from y.y.y.y:38309 to z.z.z.z:2083 length 263
(1) User-Name = 'user'
(1) NAS-IP-Address = x.x.x.x
(1) NAS-Identifier = 'NAS'
(1) Called-Station-Id = '000000000000:SSID'
(1) NAS-Port-Type = Wireless-802.11
(1) NAS-Port = 0
(1) Calling-Station-Id = '111111111111'
(1) Connect-Info = 'CONNECT 0Mbps 802.11b'
(1) Acct-Session-Id = '5501AFCF-00000020'
(1) Framed-MTU = 1400
(1) EAP-Message =
0x0210002c17010000030300406e414a35103ee4e0860100000b050000f27bc26235ef1b663594aadd343a6ab4
(1) State = 0xffabd5a1e2e5fc51254946eda3439a4f92703fe4a5ecd73b05bfad82ee821f95
(1) Message-Authenticator = 0xfc792a3aae3b5a6322f357a3821bc0f2
(1) Event-Timestamp = 'Mar 12 2015 12:32:12 EDT'
(1) Proxy-State = 0x3738
Thread 2 waiting to be assigned a request
(1) Clearing existing &reply: attributes
(1) Received Access-Accept Id 160 from z.z.z.z:2083 to y.y.y.y:38309 length 243
(1) MS-MPPE-Recv-Key =
0xec24ffbb118c183ed6a30981ba20c9256c23246ea17013c8cb79cef2f3f2bf77
(1) MS-MPPE-Send-Key =
0xe67b0827ac08fa7f27a364f223684d30d7173ab8137a2a91e4547207148cac2c
(1) EAP-Message = 0x03100004
(1) Message-Authenticator = 0x41cae584466f4d058da452161c4722a9
(1) Acct-Session-Id = '5501AFCF-00000020'
(1) Reply-Message = 'Access accepted : 111111111111 - 000000000000:SSID'
(1) Proxy-State = 0x3738
(1) # Executing section post-proxy from file
/usr/local/etc/raddb/sites-enabled/default
(1) post-proxy {
(1) eap: No pre-existing handler found
(1) [eap] = noop
(1) } # post-proxy = noop
(1) Found Auth-Type = Accept
(1) Auth-Type = Accept, accepting the user
(1) # Executing section post-auth from file
/usr/local/etc/raddb/sites-enabled/default
(1) post-auth {
(1) update {
(1) No attributes updated
(1) } # update = noop
(1) linelog: EXPAND Accounting-Request.%{%{Acct-Status-Type}:-unknown}
(1) linelog: --> Accounting-Request.unknown
(1) linelog: EXPAND /var/log/radius/linelog
(1) linelog: --> /var/log/radius/linelog
(1) linelog: EXPAND NAS %{Packet-Src-IP-Address} (%{NAS-IP-Address})
sent unknown Acct-Status-Type %{Acct-Status-Type}
(1) linelog: --> NAS x.x.x.x (x.x.x.x) sent unknown Acct-Status-Type
(1) [linelog] = ok
(1) [exec] = noop
(1) policy remove_reply_message_if_eap {
(1) if (&reply:EAP-Message && &reply:Reply-Message) {
(1) if (&reply:EAP-Message && &reply:Reply-Message) -> TRUE
(1) if (&reply:EAP-Message && &reply:Reply-Message) {
(1) update reply {
(1) &Reply-Message !* ANY
(1) } # update reply = noop
(1) } # if (&reply:EAP-Message && &reply:Reply-Message) = noop
(1) ... skipping else for request 1: Preceding "if" was taken
(1) } # policy remove_reply_message_if_eap = noop
(1) } # post-auth = ok
(1) Sent Access-Accept Id 78 from y.y.y.y:1812 to x.x.x.x:50204 length 179
(1) MS-MPPE-Recv-Key =
0xec24ffbb118c183ed6a30981ba20c9256c23246ea17013c8cb79cef2f3f2bf77
(1) MS-MPPE-Send-Key =
0xe67b0827ac08fa7f27a364f223684d30d7173ab8137a2a91e4547207148cac2c
(1) EAP-Message = 0x03100004
(1) Message-Authenticator = 0x41cae584466f4d058da452161c4722a9
(1) Acct-Session-Id = '5501AFCF-00000020'
(1) Finished request
Waking up in 0.1 seconds.
Waking up in 4.1 seconds.
Waking up in 0.3 seconds.
Thread 3 got semaphore
Thread 3 handling request 2, (1 handled so far)
(2) Received Accounting-Request Id 79 from x.x.x.x:50205 to
y.y.y.y:1813 length 233
(2) Acct-Session-Id = '5501AFCF-00000020'
(2) Event-Timestamp = 'Mar 12 2015 12:32:14 EDT'
(2) Acct-Status-Type = Start
(2) Acct-Authentic = RADIUS
(2) User-Name = 'user at realm'
(2) NAS-IP-Address = x.x.x.x
(2) NAS-Identifier = 'NAS'
(2) Called-Station-Id = '000000000000:SSID'
(2) NAS-Port-Type = Wireless-802.11
(2) NAS-Port = 0
(2) Calling-Station-Id = '111111111111'
(2) Connect-Info = 'CONNECT 0Mbps 802.11b'
(2) Acct-Session-Id = '5501AFCF-00000020'
(2) Framed-IP-Address = 10.0.26.250
(2) Acct-Delay-Time = 0
(2) # Executing section preacct from file
/usr/local/etc/raddb/sites-enabled/default
(2) preacct {
(2) [preprocess] = ok
(2) policy acct_unique {
(2) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) {
(2) EXPAND %{string:Class}
(2) -->
(2) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) -> FALSE
(2) else {
(2) update request {
(2) EXPAND
%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}
(2) --> e06f725dd6dcaefd689e573425e46b70
(2) &Acct-Unique-Session-Id := "e06f725dd6dcaefd689e573425e46b70"
(2) } # update request = noop
(2) } # else = noop
(2) } # policy acct_unique = noop
(2) suffix: Checking for suffix after "@"
(2) suffix: Looking up realm "realm" for User-Name = "user at realm"
(2) suffix: Found realm "realm"
(2) suffix: Adding Stripped-User-Name = "user"
(2) suffix: Adding Realm = "realm"
(2) suffix: Proxying request from user user to realm realm
(2) suffix: Preparing to proxy accounting request to realm "realm"
(2) [suffix] = updated
(2) [files] = noop
(2) } # preacct = updated
(2) # Executing section accounting from file
/usr/local/etc/raddb/sites-enabled/default
(2) accounting {
(2) detail: EXPAND
/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
(2) detail: --> /var/log/radius/radacct/x.x.x.x/detail-20150312
(2) detail: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
expands to /var/log/radius/radacct/x.x.x.x/detail-20150312
(2) detail: EXPAND %t
(2) detail: --> Thu Mar 12 12:32:14 2015
(2) [detail] = ok
(2) linelog: EXPAND Accounting-Request.%{%{Acct-Status-Type}:-unknown}
(2) linelog: --> Accounting-Request.Start
(2) linelog: EXPAND /var/log/radius/linelog
(2) linelog: --> /var/log/radius/linelog
(2) linelog: EXPAND
%{Acct-Status-Type}|%{Acct-Unique-Session-Id}|%{Acct-Session-Id}|%{Called-Station-Id}|%{Called-Station-SSID}|%{Calling-Station-Id}|%{NAS-IP-Address}|%{Framed-IP-Address}|%{NAS-Identifier}|%{User-Name}|NULL|NULL|NULL|NULL|NULL|%{Event-Timestamp}|NULL
(2) linelog: -->
Start|e06f725dd6dcaefd689e573425e46b70|5501AFCF-00000020|000000000000:SSID||111111111111|x.x.x.x|10.0.26.250|NAS|user at realm|NULL|NULL|NULL|NULL|NULL|Mar
12 2015 12:32:14 EDT|NULL
(2) [linelog] = ok
(2) radutmp: EXPAND /var/log/radius/radutmp
(2) radutmp: --> /var/log/radius/radutmp
(2) radutmp: EXPAND %{User-Name}
(2) radutmp: --> user at realm
(2) [radutmp] = ok
(2) sradutmp: EXPAND /var/log/radius/sradutmp
(2) sradutmp: --> /var/log/radius/sradutmp
(2) sradutmp: EXPAND %{User-Name}
(2) sradutmp: --> user at realm
(2) [sradutmp] = ok
(2) [exec] = noop
(2) attr_filter.accounting_response: EXPAND %{User-Name}
(2) attr_filter.accounting_response: --> user at realm
(2) attr_filter.accounting_response: Matched entry DEFAULT at line 14
(2) [attr_filter.accounting_response] = updated
(2) } # accounting = updated
Opening new proxy socket 'proxy (0.0.0.0, 0) -> home_server (z.z.z.z, 2084)'
Waking up in 0.4 seconds.
Waking up in 0.7 seconds.
Waking up in 0.7 seconds.
Received conflicting packet from client AP-Name port 50205 - ID: 79
due to unfinished request. Giving up on old request.
Threads: total/active/spare threads = 5/1/4
Waking up in 0.3 seconds.
Thread 1 got semaphore
Thread 1 handling request 3, (1 handled so far)
(3) Received Accounting-Request Id 79 from x.x.x.x:50205 to
y.y.y.y:1813 length 233
(3) Acct-Session-Id = '5501AFCF-00000020'
(3) Event-Timestamp = 'Mar 12 2015 12:32:14 EDT'
(3) Acct-Status-Type = Start
(3) Acct-Authentic = RADIUS
(3) User-Name = 'user at realm'
(3) NAS-IP-Address = x.x.x.x
(3) NAS-Identifier = 'NAS'
(3) Called-Station-Id = '000000000000:SSID'
(3) NAS-Port-Type = Wireless-802.11
(3) NAS-Port = 0
(3) Calling-Station-Id = '111111111111'
(3) Connect-Info = 'CONNECT 0Mbps 802.11b'
(3) Acct-Session-Id = '5501AFCF-00000020'
(3) Framed-IP-Address = 10.0.26.250
(3) Acct-Delay-Time = 2
(3) # Executing section preacct from file
/usr/local/etc/raddb/sites-enabled/default
(3) preacct {
(3) [preprocess] = ok
(3) policy acct_unique {
(3) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) {
(3) EXPAND %{string:Class}
(3) -->
(3) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) -> FALSE
(3) else {
(3) update request {
(3) EXPAND
%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}
(3) --> e06f725dd6dcaefd689e573425e46b70
(3) &Acct-Unique-Session-Id := "e06f725dd6dcaefd689e573425e46b70"
(3) } # update request = noop
(3) } # else = noop
(3) } # policy acct_unique = noop
(3) suffix: Checking for suffix after "@"
(3) suffix: Looking up realm "realm" for User-Name = "user at realm"
(3) suffix: Found realm "realm"
(3) suffix: Adding Stripped-User-Name = "user"
(3) suffix: Adding Realm = "realm"
(3) suffix: Proxying request from user user to realm realm
(3) suffix: Preparing to proxy accounting request to realm "realm"
(3) [suffix] = updated
(3) [files] = noop
(3) } # preacct = updated
(3) # Executing section accounting from file
/usr/local/etc/raddb/sites-enabled/default
(3) accounting {
(3) detail: EXPAND
/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
(3) detail: --> /var/log/radius/radacct/x.x.x.x/detail-20150312
(3) detail: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
expands to /var/log/radius/radacct/x.x.x.x/detail-20150312
(3) detail: EXPAND %t
(3) detail: --> Thu Mar 12 12:32:16 2015
(3) [detail] = ok
(3) linelog: EXPAND Accounting-Request.%{%{Acct-Status-Type}:-unknown}
(3) linelog: --> Accounting-Request.Start
(3) linelog: EXPAND /var/log/radius/linelog
(3) linelog: --> /var/log/radius/linelog
(3) linelog: EXPAND
%{Acct-Status-Type}|%{Acct-Unique-Session-Id}|%{Acct-Session-Id}|%{Called-Station-Id}|%{Called-Station-SSID}|%{Calling-Station-Id}|%{NAS-IP-Address}|%{Framed-IP-Address}|%{NAS-Identifier}|%{User-Name}|NULL|NULL|NULL|NULL|NULL|%{Event-Timestamp}|NULL
(3) linelog: -->
Start|e06f725dd6dcaefd689e573425e46b70|5501AFCF-00000020|000000000000:SSID||111111111111|x.x.x.x|10.0.26.250|NAS|user at realm|NULL|NULL|NULL|NULL|NULL|Mar
12 2015 12:32:14 EDT|NULL
(3) [linelog] = ok
(3) radutmp: EXPAND /var/log/radius/radutmp
(3) radutmp: --> /var/log/radius/radutmp
(3) radutmp: EXPAND %{User-Name}
(3) radutmp: --> user at realm
rlm_radutmp: Login entry for NAS AP-Name port 0 duplicate
(3) [radutmp] = ok
(3) sradutmp: EXPAND /var/log/radius/sradutmp
(3) sradutmp: --> /var/log/radius/sradutmp
(3) sradutmp: EXPAND %{User-Name}
(3) sradutmp: --> user at realm
rlm_radutmp: Login entry for NAS AP-Name port 0 duplicate
(3) [sradutmp] = ok
(3) [exec] = noop
(3) attr_filter.accounting_response: EXPAND %{User-Name}
(3) attr_filter.accounting_response: --> user at realm
(3) attr_filter.accounting_response: Matched entry DEFAULT at line 14
(3) [attr_filter.accounting_response] = updated
(3) } # accounting = updated
(0) <done>: Cleaning up request packet ID 77 with timestamp +5
Waking up in 0.4 seconds.
Waking up in 0.1 seconds.
(1) <done>: Cleaning up request packet ID 78 with timestamp +6
Failed opening proxy socket 'proxy (0.0.0.0, 0) -> home_server
(z.z.z.z, 2084)' : Failed in connect(): Connection timed out
Failed to insert request into the proxy list
More information about the Freeradius-Users
mailing list