FreeRADIUS not sending "Access-Accept" for Cisco Phone
Hi, 802.1x Authentication with EAP-TLS, works perfectly with a Centos client, however not from a Cisco IP Phone. Basic Specs For Server; * Centos 7.2 x64 * freeradius-3.0.4-6.el7.x86_64 * Communicating through a Dell N3000 switch. * Cisco 7841 IP Phone I've been studying the debug logs as best I can, the working log clearly shows "Sending Access Accept Packet" (output below). However when I read the debug for the Cisco phone connection, we see hundreds (would eventually be thousands) of attempts without ever seeing the below successful packet sent back. I'm just after any suggestions on how to better debug the connection from the Cisco phone? ---------- CUT (working example with Centos Client) --------------- Sending Access-Accept packet to host 192.168.11.62 port 34495, id=119, length=0 (6) MS-MPPE-Recv-Key = 0x069dfe1c5f6660fe98f7d39c311e1c52bea7445e54d05f2706c154542ed5b3fa (6) MS-MPPE-Send-Key = 0x54782fc7b655096c1a45437c1cae96d4217867c8403c0f1edd3a8438330aad81 (6) EAP-MSK = 0x069dfe1c5f6660fe98f7d39c311e1c52bea7445e54d05f2706c154542ed5b3fa 54782fc7b655096c1a45437c1cae96d4217867c8403c0f1edd3a8438330aad81 (6) EAP-EMSK = 0xcfa717399d049b7ca5f438a07c6bffc0e199bd24182a903fd759c84eb13765feda5bfd396f403068ef377c20c0ea46c2628917fd644afd54556a00b79652fa3a (6) EAP-Session-Id = 0x0d57469718eb7768f033c8f06c17b709ca49254502c930e10641848a9551823e395746989ca0c8126d5fe044a497974be973775d2f5f3b401cc023e449ef983787 (6) EAP-Message = 0x03160004 (6) Message-Authenticator = 0x00000000000000000000000000000000 (6) User-Name = 'craig' Sending Access-Accept Id 119 from 192.168.11.61:1812 to 192.168.11.62:34495 MS-MPPE-Recv-Key = 0x069dfe1c5f6660fe98f7d39c311e1c52bea7445e54d05f2706c154542ed5b3fa MS-MPPE-Send-Key = 0x54782fc7b655096c1a45437c1cae96d4217867c8403c0f1edd3a8438330aad81 EAP-Message = 0x03160004 Message-Authenticator = 0x00000000000000000000000000000000 User-Name = 'craig' (6) Finished request ---------- CUT ------------------------------------------ Regards, Craig
On May 26, 2016, at 3:44 AM, craig@mypenguin.net.au wrote:
802.1x Authentication with EAP-TLS, works perfectly with a Centos client, however not from a Cisco IP Phone.
Basic Specs For Server; * Centos 7.2 x64 * freeradius-3.0.4-6.el7.x86_64
3.0.11 would be better... but OK
* Communicating through a Dell N3000 switch. * Cisco 7841 IP Phone
I've been studying the debug logs as best I can, the working log clearly shows "Sending Access Accept Packet" (output below).
Which tells you it works. i.e. there's no new information in the log.
However when I read the debug for the Cisco phone connection, we see hundreds (would eventually be thousands) of attempts without ever seeing the below successful packet sent back.
So... what is the debug output when it goes wrong?
I'm just after any suggestions on how to better debug the connection from the Cisco phone?
Read the debug output when the Cisco phone connects? Alan DeKok.
Ok I've upgraded to freeradius-server-3.0.11 Below is the output I get from the Cisco phone attempt, this is iteration "320" and it just continues to make attempts (i assume because it's UDP)? ================================================================================================================================================================== (320) Received Access-Request Id 17 from 192.168.11.62:34495 to 192.168.11.61:1812 length 288 (320) User-Name = "CP-7841-SEPF07816D1207E" (320) Called-Station-Id = "f8-b1-56-6f-15-d6" (320) Calling-Station-Id = "f0:78:16:d1:20:7e" (320) NAS-Identifier = "f8-b1-56-6f-15-d4" (320) NAS-IP-Address = 192.168.11.62 (320) NAS-Port = 112 (320) Framed-MTU = 1500 (320) NAS-Port-Type = Ethernet (320) State = 0x7d8fc9d87d2bc4167bd29e25682eecf2 (320) EAP-Message = 0x02a4007c0d8000000072160301006d0100006903035c452fa402c853860cd34fcff40565ec53ec45be8cf56a5ed4643fefd588dc6300000ac030c02f0035002f00ff01000036000b000403000102000a000a00080019001800170013000d001c001a000004010501060103010201010102020403050306 (320) Message-Authenticator = 0x0162446871ec20dd4a2638fd7278064c (320) session-state: No cached attributes (320) # Executing section authorize from file /usr/local/freeradius/etc/raddb/sites-enabled/default (320) authorize { (320) policy filter_username { (320) if (!&User-Name) { (320) if (!&User-Name) -> FALSE (320) if (&User-Name =~ / /) { (320) if (&User-Name =~ / /) -> FALSE (320) if (&User-Name =~ /@.*@/ ) { (320) if (&User-Name =~ /@.*@/ ) -> FALSE (320) if (&User-Name =~ /\\.\\./ ) { (320) if (&User-Name =~ /\\.\\./ ) -> FALSE (320) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { (320) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE (320) if (&User-Name =~ /\\.$/) { (320) if (&User-Name =~ /\\.$/) -> FALSE (320) if (&User-Name =~ /@\\./) { (320) if (&User-Name =~ /@\\./) -> FALSE (320) } # policy filter_username = notfound (320) [preprocess] = ok (320) [digest] = noop (320) suffix: Checking for suffix after "@" (320) suffix: No '@' in User-Name = "CP-7841-SEPF07816D1207E", looking up realm NULL (320) suffix: No such realm "NULL" (320) [suffix] = noop (320) eap: Peer sent EAP Response (code 2) ID 164 length 124 (320) eap: No EAP Start, assuming it's an on-going EAP conversation (320) [eap] = updated (320) [files] = noop (320) [expiration] = noop (320) [logintime] = noop (320) [pap] = noop (320) } # authorize = updated (320) Found Auth-Type = eap (320) # Executing group from file /usr/local/freeradius/etc/raddb/sites-enabled/default (320) authenticate { (320) eap: Expiring EAP session with state 0x59e62fe75ae3223b (320) eap: Finished EAP session with state 0x7d8fc9d87d2bc416 (320) eap: Previous EAP request found for state 0x7d8fc9d87d2bc416, released from the list (320) eap: Peer sent packet with method EAP TLS (13) (320) eap: Calling submodule eap_tls to process data (320) eap_tls: Continuing EAP-TLS (320) eap_tls: Peer indicated complete TLS record size will be 114 bytes (320) eap_tls: Got complete TLS record (114 bytes) (320) eap_tls: [eaptls verify] = length included (320) eap_tls: (other): before/accept initialization (320) eap_tls: TLS_accept: before/accept initialization (320) eap_tls: <<< recv TLS 1.2 [length 006d] (320) eap_tls: TLS_accept: SSLv3 read client hello A (320) eap_tls: >>> send TLS 1.2 [length 0059] (320) eap_tls: TLS_accept: SSLv3 write server hello A (320) eap_tls: >>> send TLS 1.2 [length 0816] (320) eap_tls: TLS_accept: SSLv3 write certificate A (320) eap_tls: >>> send TLS 1.2 [length 014d] (320) eap_tls: TLS_accept: SSLv3 write key exchange A (320) eap_tls: >>> send TLS 1.2 [length 0073] (320) eap_tls: TLS_accept: SSLv3 write certificate request A (320) eap_tls: TLS_accept: SSLv3 flush data (320) eap_tls: TLS_accept: Need to read more data: SSLv3 read client certificate A (320) eap_tls: TLS_accept: Need to read more data: SSLv3 read client certificate A (320) eap_tls: In SSL Handshake Phase (320) eap_tls: In SSL Accept mode (320) eap_tls: [eaptls process] = handled (320) eap: Sending EAP Request (code 1) ID 165 length 1004 (320) eap: EAP session adding &reply:State = 0x7d8fc9d87c2ac416 (320) [eap] = handled (320) } # authenticate = handled (320) Using Post-Auth-Type Challenge (320) Post-Auth-Type sub-section not found. Ignoring. (320) # Executing group from file /usr/local/freeradius/etc/raddb/sites-enabled/default (320) Sent Access-Challenge Id 17 from 192.168.11.61:1812 to 192.168.11.62:34495 length 0 (320) EAP-Message = 0x01a503ec0dc000000a43160303005902000055030357478e00dd7b5997bbb83b60ba5536c72cc6bf4cc099ed8246b5d6ba09b8eb30206df24a0f79a02af8687ebf21332b9e9a3fbf6b849f47f5a008b1eac24bd4d481c03000000dff01000100000b00040300010216030308160b00081200080f000452 (320) Message-Authenticator = 0x00000000000000000000000000000000 (320) State = 0x7d8fc9d87c2ac4167bd29e25682eecf2 (320) Finished request (320) Cleaning up request packet ID 17 with timestamp +435 ================================================================================================================================================================== cheers Craig
Ok I've upgraded to freeradius-server-3.0.11 Below is the output I get from the Cisco phone attempt, this is iteration "320" and it just continues to make attempts (i assume because it's UDP)? ================================================================================================================================================================== (320) Received Access-Request Id 17 from 192.168.11.62:34495 to 192.168.11.61:1812 length 288 (320) User-Name = "CP-7841-SEPF07816D1207E" (320) Called-Station-Id = "f8-b1-56-6f-15-d6" (320) Calling-Station-Id = "f0:78:16:d1:20:7e" (320) NAS-Identifier = "f8-b1-56-6f-15-d4" (320) NAS-IP-Address = 192.168.11.62 (320) NAS-Port = 112 (320) Framed-MTU = 1500 (320) NAS-Port-Type = Ethernet (320) State = 0x7d8fc9d87d2bc4167bd29e25682eecf2 (320) EAP-Message = 0x02a4007c0d8000000072160301006d0100006903035c452fa402c853860cd34fcff40565ec53ec45be8cf56a5ed4643fefd588dc6300000ac030c02f0035002f00ff01000036000b000403000102000a000a00080019001800170013000d001c001a000004010501060103010201010102020403050 +306 (320) Message-Authenticator = 0x0162446871ec20dd4a2638fd7278064c (320) session-state: No cached attributes (320) # Executing section authorize from file /usr/local/freeradius/etc/raddb/sites-enabled/default (320) authorize { (320) policy filter_username { (320) if (!&User-Name) { (320) if (!&User-Name) -> FALSE (320) if (&User-Name =~ / /) { (320) if (&User-Name =~ / /) -> FALSE (320) if (&User-Name =~ /@.*@/ ) { (320) if (&User-Name =~ /@.*@/ ) -> FALSE (320) if (&User-Name =~ /\\.\\./ ) { (320) if (&User-Name =~ /\\.\\./ ) -> FALSE (320) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { (320) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE (320) if (&User-Name =~ /\\.$/) { (320) if (&User-Name =~ /\\.$/) -> FALSE (320) if (&User-Name =~ /@\\./) { (320) if (&User-Name =~ /@\\./) -> FALSE (320) } # policy filter_username = notfound (320) [preprocess] = ok (320) [digest] = noop (320) suffix: Checking for suffix after "@" (320) suffix: No '@' in User-Name = "CP-7841-SEPF07816D1207E", looking up realm NULL (320) suffix: No such realm "NULL" (320) [suffix] = noop (320) eap: Peer sent EAP Response (code 2) ID 164 length 124 (320) eap: No EAP Start, assuming it's an on-going EAP conversation (320) [eap] = updated (320) [files] = noop (320) [expiration] = noop (320) [logintime] = noop (320) [pap] = noop (320) } # authorize = updated (320) Found Auth-Type = eap (320) # Executing group from file /usr/local/freeradius/etc/raddb/sites-enabled/default (320) authenticate { (320) eap: Expiring EAP session with state 0x59e62fe75ae3223b (320) eap: Finished EAP session with state 0x7d8fc9d87d2bc416 (320) eap: Previous EAP request found for state 0x7d8fc9d87d2bc416, released from the list (320) eap: Peer sent packet with method EAP TLS (13) (320) eap: Calling submodule eap_tls to process data (320) eap_tls: Continuing EAP-TLS (320) eap_tls: Peer indicated complete TLS record size will be 114 bytes (320) eap_tls: Got complete TLS record (114 bytes) (320) eap_tls: [eaptls verify] = length included (320) eap_tls: (other): before/accept initialization (320) eap_tls: TLS_accept: before/accept initialization (320) eap_tls: <<< recv TLS 1.2 [length 006d] (320) eap_tls: TLS_accept: SSLv3 read client hello A (320) eap_tls: >>> send TLS 1.2 [length 0059] (320) eap_tls: TLS_accept: SSLv3 write server hello A (320) eap_tls: >>> send TLS 1.2 [length 0816] (320) eap_tls: TLS_accept: SSLv3 write certificate A (320) eap_tls: >>> send TLS 1.2 [length 014d] (320) eap_tls: TLS_accept: SSLv3 write key exchange A (320) eap_tls: >>> send TLS 1.2 [length 0073] (320) eap_tls: TLS_accept: SSLv3 write certificate request A (320) eap_tls: TLS_accept: SSLv3 flush data (320) eap_tls: TLS_accept: Need to read more data: SSLv3 read client certificate A (320) eap_tls: TLS_accept: Need to read more data: SSLv3 read client certificate A (320) eap_tls: In SSL Handshake Phase (320) eap_tls: In SSL Accept mode (320) eap_tls: [eaptls process] = handled (320) eap: Sending EAP Request (code 1) ID 165 length 1004 (320) eap: EAP session adding &reply:State = 0x7d8fc9d87c2ac416 (320) [eap] = handled (320) } # authenticate = handled (320) Using Post-Auth-Type Challenge (320) Post-Auth-Type sub-section not found. Ignoring. (320) # Executing group from file /usr/local/freeradius/etc/raddb/sites-enabled/default (320) Sent Access-Challenge Id 17 from 192.168.11.61:1812 to 192.168.11.62:34495 length 0 (320) EAP-Message = 0x01a503ec0dc000000a43160303005902000055030357478e00dd7b5997bbb83b60ba5536c72cc6bf4cc099ed8246b5d6ba09b8eb30206df24a0f79a02af8687ebf21332b9e9a3fbf6b849f47f5a008b1eac24bd4d481c03000000dff01000100000b00040300010216030308160b00081200080f000 +452 (320) Message-Authenticator = 0x00000000000000000000000000000000 (320) State = 0x7d8fc9d87c2ac4167bd29e25682eecf2 (320) Finished request (320) Cleaning up request packet ID 17 with timestamp +435 ================================================================================================================================================================== cheers Craig
On May 26, 2016, at 8:32 PM, craig@mypenguin.net.au wrote:
Ok I've upgraded to freeradius-server-3.0.11 Below is the output I get from the Cisco phone attempt, this is iteration "320" and it just continues to make attempts (i assume because it's UDP)?
It's continuing to make attempts because it's repeatedly trying to login. Looking at one packet is nice, but not helpful. You need to post the START of an authentication attempt, all the way to the END of that authentication attempt. If you're not sure, 20-30 packets in a row should be enough. And then READ the debug output, looking for error messages, warnings, etc. If there's no such messages, then your choices are more limited. The Cisco phone doesn't like *something* about FreeRADIUS. It's hard to find out what it doesn't like, as the phone won't produce useful logs. Maybe disable_tlsv1_2 i the EAP module? So... since FreeRADIUS works with everything, I'd blame the phone. It's broken. Alan DeKok.
participants (2)
-
Alan DeKok -
craig＠mypenguin.net.au