Hi, I have freeradius 3.0.20 with tls cache enabled (fast reauthentication) running in docker container , sql backend. Everything has been working fine until recently new device (laptop) was added to network. Laptop connects properly to specified network but when roaming it gets answer Access-Accept without any AVP, thus it is assigned to native, trunk network. Since it applies only to one device (MacBook Pro) and debug doesn’t throw any errors I don’t know where to start troubleshooting. I’d removed content of tlscache folder, toggled off/on cache and it didn’t help. Any suggestion? Martin
On Sep 9, 2019, at 2:07 AM, Marcin Marszałkowski <m.marszal@wp.pl> wrote:
Hi,
I have freeradius 3.0.20 with tls cache enabled (fast reauthentication) running in docker container , sql backend. Everything has been working fine until recently new device (laptop) was added to network. Laptop connects properly to specified network but when roaming it gets answer Access-Accept without any AVP, thus it is assigned to native, trunk network. Since it applies only to one device (MacBook Pro) and debug doesn’t throw any errors
It *does* show you what the server is doing, and *why* it added attributes to Access-Accept.
I don’t know where to start troubleshooting. I’d removed content of tlscache folder, toggled off/on cache and it didn’t help. Any suggestion?
Read the debug output. If it's too confusing, post it here. Alan DeKok.
Alan DeKok <aland@deployingradius.com> w dniu 09.09.2019, o godz. 15:43: It *does* show you what the server is doing, and *why* it added attributes to Access-Accept.
So, I've run a couple of tests (roaming between clients) with cache disabled and enabled. Cache disabled debug: (11) eap: Expiring EAP session with state 0x8afdaa7a8369b374 (11) eap: Finished EAP session with state 0x8afdaa7a8369b374 (11) eap: Previous EAP request found for state 0x8afdaa7a8369b374, released from the list (11) eap: Peer sent packet with method EAP PEAP (25) (11) eap: Calling submodule eap_peap to process data (11) eap_peap: Continuing EAP-TLS (11) eap_peap: [eaptls verify] = ok (11) eap_peap: Done initial handshake (11) eap_peap: [eaptls process] = ok (11) eap_peap: Session established. Decoding tunneled attributes (11) eap_peap: PEAP state send tlv success (11) eap_peap: Received EAP-TLV response (11) eap_peap: Success (11) eap_peap: Using saved attributes from the original Access-Accept (11) eap_peap: Session-Timeout = 86400 (11) eap_peap: Termination-Action = RADIUS-Request (11) eap_peap: Fall-Through = Yes (11) eap_peap: Acct-Interim-Interval = 300 (11) eap_peap: Tunnel-Type = VLAN (11) eap_peap: Tunnel-Medium-Type = IEEE-802 (11) eap_peap: Tunnel-Private-Group-Id = "14" (11) eap_peap: User-Name = "Martin" (11) eap: Sending EAP Success (code 3) ID 148 length 4 (11) eap: Freeing handler (11) [eap] = ok (11) } # authenticate = ok Cache enabled debug: (18) eap: Expiring EAP session with state 0x9049ed0d92dcf470 (18) eap: Finished EAP session with state 0x9049ed0d92dcf470 (18) eap: Previous EAP request found for state 0x9049ed0d92dcf470, released from the list (18) eap: Peer sent packet with method EAP PEAP (25) (18) eap: Calling submodule eap_peap to process data (18) eap_peap: Continuing EAP-TLS (18) eap_peap: [eaptls verify] = ok (18) eap_peap: Done initial handshake (18) eap_peap: [eaptls process] = ok (18) eap_peap: Session established. Decoding tunneled attributes (18) eap_peap: PEAP state send tlv success (18) eap_peap: Received EAP-TLV response (18) eap_peap: Success (18) eap_peap: No saved attributes in the original Access-Accept (18) eap_peap: &request:EAP-Session-Resumed := 1 (18) eap: Sending EAP Success (code 3) ID 149 length 4 (18) eap: Freeing handler (18) [eap] = ok (18) } # authenticate = ok Without cache, all AVP are retrieved from sql; with cache that step is skipped and cache doesn’t save AVP. If it’s required, I can post full debug or attached it as file ;-) Any ideas what might be going wrong with saving AVP in cache?
On Sep 11, 2019, at 5:28 AM, Marcin Marszałkowski <m.marszal@wp.pl> wrote:
So, I've run a couple of tests (roaming between clients) with cache disabled and enabled. ... Cache enabled debug:
(18) eap: Expiring EAP session with state 0x9049ed0d92dcf470 (18) eap: Finished EAP session with state 0x9049ed0d92dcf470 (18) eap: Previous EAP request found for state 0x9049ed0d92dcf470, released from the list (18) eap: Peer sent packet with method EAP PEAP (25) (18) eap: Calling submodule eap_peap to process data (18) eap_peap: Continuing EAP-TLS (18) eap_peap: [eaptls verify] = ok (18) eap_peap: Done initial handshake (18) eap_peap: [eaptls process] = ok (18) eap_peap: Session established. Decoding tunneled attributes (18) eap_peap: PEAP state send tlv success (18) eap_peap: Received EAP-TLV response (18) eap_peap: Success (18) eap_peap: No saved attributes in the original Access-Accept (18) eap_peap: &request:EAP-Session-Resumed := 1 (18) eap: Sending EAP Success (code 3) ID 149 length 4 (18) eap: Freeing handler (18) [eap] = ok (18) } # authenticate = ok
There are a LOT more messages than that. Including messages which talk about restoring cached attributes. Honestly, *read* the debug output. ALL OF IT. If there's nothing about the cache, then you didn't configure the cache properly. I fail to understand why you're only looking at the final access accept. The REST of the debug output shows more information about previous actions, like caching...
Without cache, all AVP are retrieved from sql; with cache that step is skipped and cache doesn’t save AVP.
Yes, if you *read* the debug outputs you'll see why. There's no "inner-tunnel" being run for the cached session.
If it’s required, I can post full debug or attached it as file ;-) Any ideas what might be going wrong with saving AVP in cache?
TBH, first upgrade to the v3.0.x branch on GitHub. I'm pretty sure I already suggest this. That makes caching easier to configure. See the "cache" section of mods-available/eap in the v3.0.x source. Then, READ the debug output. ALL OF IT. Do simple things like LOOK FOR THE WORD "cache" or "caching". The more you ignore the debug output, the harder it will be for you to understand the problem and fix it. Alan DeKok.
Alan DeKok <aland@deployingradius.com> w dniu 11.09.2019, o godz. 13:19: I fail to understand why you're only looking at the final access accept. The REST of the debug output shows more information about previous actions, like caching...
I’ve read all debug. Simply I pasted a part which, acc. to me, was the most relevant and I asked if it’s required, I’ll post full debug output.
TBH, first upgrade to the v3.0.x branch on GitHub. I'm pretty sure I already suggest this. That makes caching easier to configure. See the "cache" section of mods-available/eap in the v3.0.x source.
Quoting myself from the first post:
I have freeradius 3.0.20 with tls cache enabled (fast reauthentication) running in docker container , sql backend.
I don’t ignore the debug output - as above. Debug when cache was enabled. If I had misconfigured something, please let me know it. Ready to process requests (15) Received Access-Request Id 6 from 172.16.0.5:57339 to 172.16.0.12:1812 length 192 (15) User-Name = "Mark" (15) NAS-Identifier = "feecfa8ceda8" (15) Called-Station-Id = "FE-EC-FA-8C-ED-A8:Site" (15) NAS-Port-Type = Wireless-802.11 (15) Service-Type = Framed-User (15) Calling-Station-Id = "A8-63-C7-20-G6-AC" (15) Connect-Info = "CONNECT 0Mbps 802.11b" (15) Acct-Session-Id = "455712F874FB7544" (15) WLAN-Pairwise-Cipher = 1027076 (15) WLAN-Group-Cipher = 1027076 (15) WLAN-AKM-Suite = 1027073 (15) Framed-MTU = 1400 (15) EAP-Message = 0x0292000b014d617263696e (15) Message-Authenticator = 0x4d1287cfd245307c0832320a26c8b43c (15) # Executing section authorize from file /etc/freeradius/sites-enabled/default (15) authorize { (15) policy filter_username { (15) if (&User-Name) { (15) if (&User-Name) -> TRUE (15) if (&User-Name) { (15) if (&User-Name =~ / /) { (15) if (&User-Name =~ / /) -> FALSE (15) if (&User-Name =~ /@[^@]*@/ ) { (15) if (&User-Name =~ /@[^@]*@/ ) -> FALSE (15) if (&User-Name =~ /\.\./ ) { (15) if (&User-Name =~ /\.\./ ) -> FALSE (15) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (15) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (15) if (&User-Name =~ /\.$/) { (15) if (&User-Name =~ /\.$/) -> FALSE (15) if (&User-Name =~ /@\./) { (15) if (&User-Name =~ /@\./) -> FALSE (15) } # if (&User-Name) = notfound (15) } # policy filter_username = notfound (15) [preprocess] = ok (15) update request { rlm_sql (sql): Reserved connection (8) rlm_sql (sql): Released connection (8) (15) EXPAND %{User-Name} (15) --> Mark (15) SQL-User-Name set to 'Mark' rlm_sql (sql): Reserved connection (6) (15) Executing select query: select groupname from radhuntgroup where nasipaddress="172.16.0.5" rlm_sql (sql): Released connection (6) (15) EXPAND %{sql:select groupname from radhuntgroup where nasipaddress="%{NAS-IP-Address}"} (15) --> WiFi (15) Huntgroup-Name := WiFi (15) } # update request = noop (15) [mschap] = noop (15) suffix: Checking for suffix after "@" (15) suffix: No '@' in User-Name = "Mark", looking up realm NULL (15) suffix: No such realm "NULL" (15) [suffix] = noop (15) eap: Peer sent EAP Response (code 2) ID 146 length 11 (15) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize (15) [eap] = ok (15) } # authorize = ok (15) Found Auth-Type = eap (15) # Executing group from file /etc/freeradius/sites-enabled/default (15) authenticate { (15) eap: Peer sent packet with method EAP Identity (1) (15) eap: Calling submodule eap_peap to process data (15) eap_peap: Initiating new TLS session (15) eap_peap: [eaptls start] = request (15) eap: Sending EAP Request (code 1) ID 147 length 6 (15) eap: EAP session adding &reply:State = 0x9049ed0d90daf470 (15) [eap] = handled (15) } # authenticate = handled (15) Using Post-Auth-Type Challenge (15) # Executing group from file /etc/freeradius/sites-enabled/default (15) Challenge { ... } # empty sub-section is ignored (15) Sent Access-Challenge Id 6 from 172.16.0.12:1812 to 172.16.0.5:57339 length 0 (15) EAP-Message = 0x019300061920 (15) Message-Authenticator = 0x00000000000000000000000000000000 (15) State = 0x9049ed0d90daf4706cd367d56f8f90f4 (15) Finished request Waking up in 2.9 seconds. (16) Received Access-Request Id 7 from 172.16.0.5:57339 to 172.16.0.12:1812 length 392 (16) User-Name = "Mark" (16) NAS-Identifier = "feecfa8ceda8" (16) Called-Station-Id = "FE-EC-FA-8C-ED-A8:Site" (16) NAS-Port-Type = Wireless-802.11 (16) Service-Type = Framed-User (16) Calling-Station-Id = "A8-63-C7-20-G6-AC" (16) Connect-Info = "CONNECT 0Mbps 802.11b" (16) Acct-Session-Id = "455712F874FB7544" (16) WLAN-Pairwise-Cipher = 1027076 (16) WLAN-Group-Cipher = 1027076 (16) WLAN-AKM-Suite = 1027073 (16) Framed-MTU = 1400 (16) EAP-Message = 0x029300c11980000000b716030100b2010000ae03035d78b9d3e77fa617afa8f1766e50e19d3b2fba7e37bb52f42d7d76263e0f08c420b262a59370281c744fe0461ed6ec84ac5cad9f13e1659976768255c81953cfe5002c00ffc02cc02bc024c023c00ac009c008c030c02fc028c027c014c013c012009d009c003d003c0035002f000a01000039000a00080006001700180019000b00020100000d00120010040102010501060104030203050306030005000501000000000012000000170000 (16) State = 0x9049ed0d90daf4706cd367d56f8f90f4 (16) Message-Authenticator = 0xd196f48cb85a135c470bbdab8054d6ee (16) session-state: No cached attributes (16) # Executing section authorize from file /etc/freeradius/sites-enabled/default (16) authorize { (16) policy filter_username { (16) if (&User-Name) { (16) if (&User-Name) -> TRUE (16) if (&User-Name) { (16) if (&User-Name =~ / /) { (16) if (&User-Name =~ / /) -> FALSE (16) if (&User-Name =~ /@[^@]*@/ ) { (16) if (&User-Name =~ /@[^@]*@/ ) -> FALSE (16) if (&User-Name =~ /\.\./ ) { (16) if (&User-Name =~ /\.\./ ) -> FALSE (16) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (16) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (16) if (&User-Name =~ /\.$/) { (16) if (&User-Name =~ /\.$/) -> FALSE (16) if (&User-Name =~ /@\./) { (16) if (&User-Name =~ /@\./) -> FALSE (16) } # if (&User-Name) = notfound (16) } # policy filter_username = notfound (16) [preprocess] = ok (16) update request { rlm_sql (sql): Reserved connection (9) rlm_sql (sql): Released connection (9) (16) EXPAND %{User-Name} (16) --> Mark (16) SQL-User-Name set to 'Mark' rlm_sql (sql): Reserved connection (8) (16) Executing select query: select groupname from radhuntgroup where nasipaddress="172.16.0.5" rlm_sql (sql): Released connection (8) (16) EXPAND %{sql:select groupname from radhuntgroup where nasipaddress="%{NAS-IP-Address}"} (16) --> WiFi (16) Huntgroup-Name := WiFi (16) } # update request = noop (16) [mschap] = noop (16) suffix: Checking for suffix after "@" (16) suffix: No '@' in User-Name = "Mark", looking up realm NULL (16) suffix: No such realm "NULL" (16) [suffix] = noop (16) eap: Peer sent EAP Response (code 2) ID 147 length 193 (16) eap: Continuing tunnel setup (16) [eap] = ok (16) } # authorize = ok (16) Found Auth-Type = eap (16) # Executing group from file /etc/freeradius/sites-enabled/default (16) authenticate { (16) eap: Expiring EAP session with state 0x9049ed0d90daf470 (16) eap: Finished EAP session with state 0x9049ed0d90daf470 (16) eap: Previous EAP request found for state 0x9049ed0d90daf470, released from the list (16) eap: Peer sent packet with method EAP PEAP (25) (16) eap: Calling submodule eap_peap to process data (16) eap_peap: Continuing EAP-TLS (16) eap_peap: Peer indicated complete TLS record size will be 183 bytes (16) eap_peap: Got complete TLS record (183 bytes) (16) eap_peap: [eaptls verify] = length included (16) eap_peap: (other): before SSL initialization (16) eap_peap: TLS_accept: before SSL initialization (16) eap_peap: TLS_accept: before SSL initialization (16) eap_peap: <<< recv TLS 1.3 [length 00b2] (16) eap_peap: Peer requested cached session: b262a59370281c744fe0461ed6ec84ac5cad9f13e1659976768255c81953cfe5 reading pairlist file /var/lib/radiusd/tlscache/b262a59370281c744fe0461ed6ec84ac5cad9f13e1659976768255c81953cfe5.vps (16) eap_peap: Successfully restored session b262a59370281c744fe0461ed6ec84ac5cad9f13e1659976768255c81953cfe5 (16) eap_peap: reply:User-Name = "Mark" (16) eap_peap: TLS_accept: SSLv3/TLS read client hello (16) eap_peap: >>> send TLS 1.2 [length 0055] (16) eap_peap: TLS_accept: SSLv3/TLS write server hello (16) eap_peap: >>> send TLS 1.2 [length 0001] (16) eap_peap: TLS_accept: SSLv3/TLS write change cipher spec (16) eap_peap: >>> send TLS 1.2 [length 0010] (16) eap_peap: TLS_accept: SSLv3/TLS write finished (16) eap_peap: TLS_accept: Need to read more data: SSLv3/TLS write finished (16) eap_peap: TLS - In Handshake Phase (16) eap_peap: TLS - got 141 bytes of data (16) eap_peap: [eaptls process] = handled (16) eap: Sending EAP Request (code 1) ID 148 length 147 (16) eap: EAP session adding &reply:State = 0x9049ed0d91ddf470 (16) [eap] = handled (16) } # authenticate = handled (16) Using Post-Auth-Type Challenge (16) # Executing group from file /etc/freeradius/sites-enabled/default (16) Challenge { ... } # empty sub-section is ignored (16) Sent Access-Challenge Id 7 from 172.16.0.12:1812 to 172.16.0.5:57339 length 0 (16) EAP-Message = 0x0194009319001603030055020000510303bf177f4921b91b495fa613e686ff5ee6c4af272d159dceb032799702386f861820b262a59370281c744fe0461ed6ec84ac5cad9f13e1659976768255c81953cfe5c030000009ff0100010000170000140303000101160303002885ffc56622cd48fc5bdefb6e60950aa3f9b63798aa0a35855b5636882e30c6488818f9d282a04f3c (16) Message-Authenticator = 0x00000000000000000000000000000000 (16) State = 0x9049ed0d91ddf4706cd367d56f8f90f4 (16) Finished request Waking up in 2.9 seconds. (17) Received Access-Request Id 8 from 172.16.0.5:57339 to 172.16.0.12:1812 length 260 (17) User-Name = "Mark" (17) NAS-Identifier = "feecfa8ceda8" (17) Called-Station-Id = "FE-EC-FA-8C-ED-A8:Site" (17) NAS-Port-Type = Wireless-802.11 (17) Service-Type = Framed-User (17) Calling-Station-Id = "A8-63-C7-20-G6-AC" (17) Connect-Info = "CONNECT 0Mbps 802.11b" (17) Acct-Session-Id = "455712F874FB7544" (17) WLAN-Pairwise-Cipher = 1027076 (17) WLAN-Group-Cipher = 1027076 (17) WLAN-AKM-Suite = 1027073 (17) Framed-MTU = 1400 (17) EAP-Message = 0x0294003d19800000003314030300010116030300286e93a15755769e052e5ec29a2ff88c31726ec46a6f32e7e2b21a944ae7e51323443b62e53643a0c6 (17) State = 0x9049ed0d91ddf4706cd367d56f8f90f4 (17) Message-Authenticator = 0x17fab878e09cdeaabd8b72a27b7343c3 (17) session-state: No cached attributes (17) # Executing section authorize from file /etc/freeradius/sites-enabled/default (17) authorize { (17) policy filter_username { (17) if (&User-Name) { (17) if (&User-Name) -> TRUE (17) if (&User-Name) { (17) if (&User-Name =~ / /) { (17) if (&User-Name =~ / /) -> FALSE (17) if (&User-Name =~ /@[^@]*@/ ) { (17) if (&User-Name =~ /@[^@]*@/ ) -> FALSE (17) if (&User-Name =~ /\.\./ ) { (17) if (&User-Name =~ /\.\./ ) -> FALSE (17) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (17) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (17) if (&User-Name =~ /\.$/) { (17) if (&User-Name =~ /\.$/) -> FALSE (17) if (&User-Name =~ /@\./) { (17) if (&User-Name =~ /@\./) -> FALSE (17) } # if (&User-Name) = notfound (17) } # policy filter_username = notfound (17) [preprocess] = ok (17) update request { rlm_sql (sql): Reserved connection (6) rlm_sql (sql): Released connection (6) (17) EXPAND %{User-Name} (17) --> Mark (17) SQL-User-Name set to 'Mark' rlm_sql (sql): Reserved connection (9) (17) Executing select query: select groupname from radhuntgroup where nasipaddress="172.16.0.5" rlm_sql (sql): Released connection (9) (17) EXPAND %{sql:select groupname from radhuntgroup where nasipaddress="%{NAS-IP-Address}"} (17) --> WiFi (17) Huntgroup-Name := WiFi (17) } # update request = noop (17) [mschap] = noop (17) suffix: Checking for suffix after "@" (17) suffix: No '@' in User-Name = "Mark", looking up realm NULL (17) suffix: No such realm "NULL" (17) [suffix] = noop (17) eap: Peer sent EAP Response (code 2) ID 148 length 61 (17) eap: Continuing tunnel setup (17) [eap] = ok (17) } # authorize = ok (17) Found Auth-Type = eap (17) # Executing group from file /etc/freeradius/sites-enabled/default (17) authenticate { (17) eap: Expiring EAP session with state 0x9049ed0d91ddf470 (17) eap: Finished EAP session with state 0x9049ed0d91ddf470 (17) eap: Previous EAP request found for state 0x9049ed0d91ddf470, released from the list (17) eap: Peer sent packet with method EAP PEAP (25) (17) eap: Calling submodule eap_peap to process data (17) eap_peap: Continuing EAP-TLS (17) eap_peap: Peer indicated complete TLS record size will be 51 bytes (17) eap_peap: Got complete TLS record (51 bytes) (17) eap_peap: [eaptls verify] = length included (17) eap_peap: TLS_accept: SSLv3/TLS write finished (17) eap_peap: TLS_accept: SSLv3/TLS read change cipher spec (17) eap_peap: <<< recv TLS 1.2 [length 0010] (17) eap_peap: TLS_accept: SSLv3/TLS read finished (17) eap_peap: (other): SSL negotiation finished successfully (17) eap_peap: TLS - Connection Established (17) eap_peap: TLS-Session-Cipher-Suite = "ECDHE-RSA-AES256-GCM-SHA384" (17) eap_peap: TLS-Session-Version = "TLS 1.2" (17) eap_peap: TLS - Application data. (17) eap_peap: Adding cached attributes from session b262a59370281c744fe0461ed6ec84ac5cad9f13e1659976768255c81953cfe5 (17) eap_peap: &reply:User-Name = "Mark" (17) eap_peap: [eaptls process] = success (17) eap_peap: Session established. Decoding tunneled attributes (17) eap_peap: PEAP state TUNNEL ESTABLISHED (17) eap_peap: Skipping Phase2 because of session resumption (17) eap_peap: SUCCESS (17) eap: Sending EAP Request (code 1) ID 149 length 46 (17) eap: EAP session adding &reply:State = 0x9049ed0d92dcf470 (17) [eap] = handled (17) } # authenticate = handled (17) Using Post-Auth-Type Challenge (17) # Executing group from file /etc/freeradius/sites-enabled/default (17) Challenge { ... } # empty sub-section is ignored (17) session-state: Saving cached attributes (17) TLS-Session-Cipher-Suite = "ECDHE-RSA-AES256-GCM-SHA384" (17) TLS-Session-Version = "TLS 1.2" (17) Sent Access-Challenge Id 8 from 172.16.0.12:1812 to 172.16.0.5:57339 length 0 (17) User-Name = "Mark" (17) EAP-Message = 0x0195002e1900170303002385ffc56622cd48fd87beea6a06aa85df798459e50fd2f6fb0b0546ecb2504b4239f144 (17) Message-Authenticator = 0x00000000000000000000000000000000 (17) State = 0x9049ed0d92dcf4706cd367d56f8f90f4 (17) Finished request Waking up in 2.9 seconds. (18) Received Access-Request Id 9 from 172.16.0.5:57339 to 172.16.0.12:1812 length 245 (18) User-Name = "Mark" (18) NAS-Identifier = "feecfa8ceda8" (18) Called-Station-Id = "FE-EC-FA-8C-ED-A8:Site" (18) NAS-Port-Type = Wireless-802.11 (18) Service-Type = Framed-User (18) Calling-Station-Id = "A8-63-C7-20-G6-AC" (18) Connect-Info = "CONNECT 0Mbps 802.11b" (18) Acct-Session-Id = "455712F874FB7544" (18) WLAN-Pairwise-Cipher = 1027076 (18) WLAN-Group-Cipher = 1027076 (18) WLAN-AKM-Suite = 1027073 (18) Framed-MTU = 1400 (18) EAP-Message = 0x0295002e190017030300236e93a15755769e064b7dbc80a24d1576b15bccb5a811ecabb99eee5f157c784478413e (18) State = 0x9049ed0d92dcf4706cd367d56f8f90f4 (18) Message-Authenticator = 0xd53788d3faf8f3cb9bc335e8fccce72b (18) Restoring &session-state (18) &session-state:TLS-Session-Cipher-Suite = "ECDHE-RSA-AES256-GCM-SHA384" (18) &session-state:TLS-Session-Version = "TLS 1.2" (18) # Executing section authorize from file /etc/freeradius/sites-enabled/default (18) authorize { (18) policy filter_username { (18) if (&User-Name) { (18) if (&User-Name) -> TRUE (18) if (&User-Name) { (18) if (&User-Name =~ / /) { (18) if (&User-Name =~ / /) -> FALSE (18) if (&User-Name =~ /@[^@]*@/ ) { (18) if (&User-Name =~ /@[^@]*@/ ) -> FALSE (18) if (&User-Name =~ /\.\./ ) { (18) if (&User-Name =~ /\.\./ ) -> FALSE (18) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (18) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (18) if (&User-Name =~ /\.$/) { (18) if (&User-Name =~ /\.$/) -> FALSE (18) if (&User-Name =~ /@\./) { (18) if (&User-Name =~ /@\./) -> FALSE (18) } # if (&User-Name) = notfound (18) } # policy filter_username = notfound (18) [preprocess] = ok (18) update request { rlm_sql (sql): Reserved connection (8) rlm_sql (sql): Released connection (8) (18) EXPAND %{User-Name} (18) --> Mark (18) SQL-User-Name set to 'Mark' rlm_sql (sql): Reserved connection (6) (18) Executing select query: select groupname from radhuntgroup where nasipaddress="172.16.0.5" rlm_sql (sql): Released connection (6) (18) EXPAND %{sql:select groupname from radhuntgroup where nasipaddress="%{NAS-IP-Address}"} (18) --> WiFi (18) Huntgroup-Name := WiFi (18) } # update request = noop (18) [mschap] = noop (18) suffix: Checking for suffix after "@" (18) suffix: No '@' in User-Name = "Mark", looking up realm NULL (18) suffix: No such realm "NULL" (18) [suffix] = noop (18) eap: Peer sent EAP Response (code 2) ID 149 length 46 (18) eap: Continuing tunnel setup (18) [eap] = ok (18) } # authorize = ok (18) Found Auth-Type = eap (18) # Executing group from file /etc/freeradius/sites-enabled/default (18) authenticate { (18) eap: Expiring EAP session with state 0x9049ed0d92dcf470 (18) eap: Finished EAP session with state 0x9049ed0d92dcf470 (18) eap: Previous EAP request found for state 0x9049ed0d92dcf470, released from the list (18) eap: Peer sent packet with method EAP PEAP (25) (18) eap: Calling submodule eap_peap to process data (18) eap_peap: Continuing EAP-TLS (18) eap_peap: [eaptls verify] = ok (18) eap_peap: Done initial handshake (18) eap_peap: [eaptls process] = ok (18) eap_peap: Session established. Decoding tunneled attributes (18) eap_peap: PEAP state send tlv success (18) eap_peap: Received EAP-TLV response (18) eap_peap: Success (18) eap_peap: No saved attributes in the original Access-Accept (18) eap_peap: &request:EAP-Session-Resumed := 1 (18) eap: Sending EAP Success (code 3) ID 149 length 4 (18) eap: Freeing handler (18) [eap] = ok (18) } # authenticate = ok (18) # Executing section post-auth from file /etc/freeradius/sites-enabled/default (18) post-auth { (18) if (!&reply:State) { (18) if (!&reply:State) -> TRUE (18) if (!&reply:State) { (18) update reply { (18) EXPAND 0x%{randstr:16h} (18) --> 0x78bca9ab293ab8e378b20bcb20a8b721c4 (18) State := 0x78bca9ab293ab8e378b20bcb20a8b721c4 (18) } # update reply = noop (18) } # if (!&reply:State) = noop (18) dailycounter: WARNING: Couldn't find check attribute, control:Max-Daily-Session, doing nothing... (18) [dailycounter] = noop (18) if (session-state:User-Name && reply:User-Name && request:User-Name && (reply:User-Name == request:User-Name)) { (18) if (session-state:User-Name && reply:User-Name && request:User-Name && (reply:User-Name == request:User-Name)) -> FALSE (18) update { (18) &reply::TLS-Session-Cipher-Suite += &session-state:TLS-Session-Cipher-Suite[*] -> 'ECDHE-RSA-AES256-GCM-SHA384' (18) &reply::TLS-Session-Version += &session-state:TLS-Session-Version[*] -> 'TLS 1.2' (18) } # update = noop (18) sql: EXPAND .query (18) sql: --> .query (18) sql: Using query template 'query' rlm_sql (sql): Reserved connection (9) (18) sql: EXPAND %{User-Name} (18) sql: --> Mark (18) sql: SQL-User-Name set to 'Mark' (18) sql: EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') (18) sql: --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'Mark', '', 'Access-Accept', '2019-09-11 11:09:39') (18) sql: Executing query: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'Mark', '', 'Access-Accept', '2019-09-11 11:09:39') (18) sql: SQL query returned: success (18) sql: 1 record(s) updated rlm_sql (sql): Released connection (9) (18) [sql] = ok (18) [exec] = noop (18) policy insert_acct_class { (18) update reply { (18) EXPAND ai:%{md5:%t,%I,%{Packet-Src-Port},%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}},%{NAS-IP-Address},%{Calling-Station-ID},%{User-Name}} (18) --> ai:c491db0a6c5840376fb8eaf636f957a8 (18) &Class = 0x61693a6334393164623061366335383430333736666238656166363336663935376138 (18) } # update reply = noop (18) } # policy insert_acct_class = noop (18) if (&reply:EAP-Session-Id) { (18) if (&reply:EAP-Session-Id) -> TRUE (18) if (&reply:EAP-Session-Id) { (18) update reply { (18) EAP-Key-Name := &reply:EAP-Session-Id -> 0x195d78b9d3e77fa617afa8f1766e50e19d3b2fba7e37bb52f42d7d76263e0f08c4bf177f4921b91b495fa613e686ff5ee6c4af272d159dceb032799702386f8618 (18) } # update reply = noop (18) } # if (&reply:EAP-Session-Id) = noop (18) policy remove_reply_message_if_eap { (18) if (&reply:EAP-Message && &reply:Reply-Message) { (18) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE (18) else { (18) [noop] = noop (18) } # else = noop (18) } # policy remove_reply_message_if_eap = noop (18) } # post-auth = ok (18) Sent Access-Accept Id 9 from 172.16.0.12:1812 to 172.16.0.5:57339 length 0 (18) MS-MPPE-Recv-Key = 0x28276f27f023b8e1ada045bbb056c5d8e8950482980f85275dc2375c8291c7b5 (18) MS-MPPE-Send-Key = 0x7bf480637f1218eb9c4d8e28b661de7ad8c6a57758bfd88181af94654af6c745 (18) EAP-Message = 0x03950004 (18) Message-Authenticator = 0x00000000000000000000000000000000 (18) User-Name = "Mark" (18) State := 0x78bca9ab293ab8e378b20bcb20a8b721c4 (18) Class = 0x61693a6334393164623061366335383430333736666238656166363336663935376138 (18) EAP-Key-Name := 0x195d78b9d3e77fa617afa8f1766e50e19d3b2fba7e37bb52f42d7d76263e0f08c4bf177f4921b91b495fa613e686ff5ee6c4af272d159dceb032799702386f8618 (18) Finished request Waking up in 2.6 seconds. (15) Cleaning up request packet ID 6 with timestamp +80 (16) Cleaning up request packet ID 7 with timestamp +80 (17) Cleaning up request packet ID 8 with timestamp +80 Waking up in 0.2 seconds. (18) Cleaning up request packet ID 9 with timestamp +80
Take a look at http://lists.freeradius.org/pipermail/freeradius-users/2016-January/081595.h... and see if that helps. If you want to allow the attributes to change between the original authentication and a reauth you'll have to modify that quite a bit and do some SQL in the outer tunnel server based on inner tunnel attributes.
On Sep 11, 2019, at 9:35 AM, Marcin Marszałkowski <m.marszal@wp.pl> wrote:
I don’t ignore the debug output - as above.
Then the question of "why are the replies different?" is answered in the debug output. Which means I'm surprised that the question was asked.
Debug when cache was enabled. If I had misconfigured something, please let me know it.
Which shows it restoring attributes from the cache:
(16) eap_peap: Successfully restored session b262a59370281c744fe0461ed6ec84ac5cad9f13e1659976768255c81953cfe5 (16) eap_peap: reply:User-Name = "Mark"
And... that's it. Did you edit the "store" subsection to list attributes for it to cache? As documented ... ? if you did that, then those attributes are cached, and then restored when the session is resumed. Alan DeKok.
Alan DeKok <aland@deployingradius.com> w dniu 11.09.2019, o godz. 18:24: Then the question of "why are the replies different?" is answered in the debug output. Which means I'm surprised that the question was asked.
„Why…” I meant to find the underlying root cause of this particular problem. I’m not developer - just a user and debug info is not as clear to me as is to you.
Did you edit the "store" subsection to list attributes for it to cache? As documented ... ?
I’ve read on wiki rlm_eap description and there’s nothing about caching. The only thing I adhered to was description in eap config file Unfortunately, I couldn’t find anything about „store” subsection. Did you mean similar problem asked about in http://freeradius.1045715.n5.nabble.com/Example-of-how-to-use-caching-Cached... ? If so, how to set caching AVP’s? I thought Cached-Session-Policy is set from the Access-Accept reply... Regards Martin
On Sep 11, 2019, at 2:26 PM, Marcin Marszałkowski <m.marszal@wp.pl> wrote:
Alan DeKok <aland@deployingradius.com> w dniu 11.09.2019, o godz. 18:24: Then the question of "why are the replies different?" is answered in the debug output. Which means I'm surprised that the question was asked.
„Why…” I meant to find the underlying root cause of this particular problem. I’m not developer - just a user and debug info is not as clear to me as is to you.
The messages are pretty clear. They show you which attributes are stored in the session cache, and which ones are retrieved from the session cache.
Did you edit the "store" subsection to list attributes for it to cache? As documented ... ?
I’ve read on wiki rlm_eap description and there’s nothing about caching. The only thing I adhered to was description in eap config file Unfortunately, I couldn’t find anything about „store” subsection.
Then you're not looking at the mods-available/eap file from the v3.0.x branch. The point of using a new version is *not* just to use the binary. But *also* to look at the updated documentation and configuration examples. So you've wasted days of time and many message just to realize that you're *not* looking at the updated examples as I suggested. Please follow instructions. It shouldn't be difficult. Every step you skip results in lost time and more frustration for everyone.
Did you mean similar problem asked about in http://freeradius.1045715.n5.nabble.com/Example-of-how-to-use-caching-Cached... ?
No. I meant to look at the "store" subsection. Which is why I said it. Alan DeKok.
Alan DeKok <aland@deployingradius.com> w dniu 11.09.2019, o godz. 20:48:
The point of using a new version is *not* just to use the binary. But *also* to look at the updated documentation and configuration examples.
So you've wasted days of time and many message just to realize that you're *not* looking at the updated examples as I suggested.
I use eap.conf file which was located in mods-available after building the server: # -*- text -*- ## ## eap.conf -- Configuration for EAP types (PEAP, TTLS, etc.) ## ## $Id: 36849e10f284fa34d43fd0d31358dd2699758625 $ ####################################################################### Now when I compared it with content of eap.conf in git folder, is of different version: # -*- text -*- ## ## eap.conf -- Configuration for EAP types (PEAP, TTLS, etc.) ## ## $Id: a89a783663588017b12bcc076362e728261ba8f2 $ ####################################################################### And obviously, this file has it: store { Tunnel-Private-Group-Id } } It looks like, that was the source of my problem. Now I need to compare/check all conf files...
On Sep 11, 2019, at 3:13 PM, Marcin Marszałkowski <m.marszal@wp.pl> wrote:
It looks like, that was the source of my problem. Now I need to compare/check all conf files...
That's really the only change necessary here. Again, if there was more to do, I would have said it. The install process does *not* over-write your existing configuration files. For very many reasons. Alan DeKok.
Marcin Marszałkowski <m.marszal@wp.pl> wrote
I have freeradius 3.0.20 with tls cache enabled (fast reauthentication) running in docker container , sql backend. Everything has been working fine until recently new device (laptop) was added to network. Laptop connects properly to specified network but when roaming it gets answer Access-Accept without any AVP, thus it is assigned to native, trunk network.
Is it possible that this is the first device that you have used on you network that actually does fast reauthentication? Many devices won't unless you tell them to. If that's the case you're not saving the necessary authorization attributes into the cache or pulling them back out. This is a bit complicated to do, as some of them may be determined inside the inner tunnel. eapol_test can be used to test fast reauthentication, you just have to do a bit of mangling of the output to find the attributes that the server is sending during a fast-reauthentication versus the ones it gets on the first authentication: eapol_test -t 4 -c <conf file with username, password, etc> -r 1 -a IP_OF_FREERADIUS -p PORT_OF_FREERADIUS -s SHARED_SECRET -M<FAKE_MAC_ADDRESS_CSID> -N4:x:0x<FAKE_NAS_IP_IN_HEX> -N30:s:<FAKE_CALLED_STATION_ADDRESS> | perl -ne '$m = 1 if m/Triggering EAP reauthentication/; $m = 0 if m/MSCHAP/; print if $m;' | grep -A1 'Attribute 81 (Tunnel-Private-Group-Id)'
Brian Julin <BJulin@clarku.edu> w dniu 09.09.2019, o godz. 16:08:
Is it possible that this is the first device that you have used on you network that actually does fast reauthentication? Many devices won't unless you tell them to.
I don’t think so, tlscache folder was already populated with files as below: 053bc53f44fec1d1539f3ddcb989f59c994cae4d6fa5363a876166d24f29b27a.asn1 053bc53f44fec1d1539f3ddcb989f59c994cae4d6fa5363a876166d24f29b27a.vps 117451d0acd2c340d0b32ffc5af16e6bd8e915dbedc3c99fd72e9c9f332cb01f.asn1 117451d0acd2c340d0b32ffc5af16e6bd8e915dbedc3c99fd72e9c9f332cb01f.vps And so on…
eapol_test can be used to test fast reauthentication, you just have to do a bit of mangling of the output to find the attributes that the server is sending during a fast-reauthentication versus the ones it gets on the first authentication:
Thanks for a hint, at first I’ll redo tests with said device and then try to use eapol_test. I’ll post debug and maybe you’ll see something in it what I’ve overlooked. Martin
Marcin Marszałkowski <m.marszal@wp.pl> wrote:
Brian Julin <BJulin@clarku.edu> w dniu 09.09.2019, o godz. 16:08:
Is it possible that this is the first device that you have used on you network that actually does fast reauthentication? Many devices won't unless you tell them to.
I don’t think so, tlscache folder was already populated with files as below: 053bc53f44fec1d1539f3ddcb989f59c994cae4d6fa5363a876166d24f29b27a.asn1 053bc53f44fec1d1539f3ddcb989f59c994cae4d6fa5363a876166d24f29b27a.vps 117451d0acd2c340d0b32ffc5af16e6bd8e915dbedc3c99fd72e9c9f332cb01f.asn1 117451d0acd2c340d0b32ffc5af16e6bd8e915dbedc3c99fd72e9c9f332cb01f.vps And so on…
The cache populates during the initial authentication... you don't need a resumption to happen to get a cache file.
Brian Julin <BJulin@clarku.edu> w dniu 09.09.2019, o godz. 16:08: Is it possible that this is the first device that you have used on you network that actually does fast reauthentication? Many devices won't unless you tell them to. Most devices are pretty new (1 to 2 years old) so, I don’t think it’s the case.
If that's the case you're not saving the necessary authorization attributes into the cache or pulling them back out. This is a bit complicated to do, as some of them may be determined inside the inner tunnel.
That’s what I think to be happening. Today I’ve disabled cache and all came back to normal. One more thing, with cache enabled, another device had problems to login - kept getting message about wrong password every couple of logins... As I haven't had much time recently, I’m going to run tests with cache enabled in next days, then I’ll post debug as well.
participants (3)
-
Alan DeKok -
Brian Julin -
Marcin Marszałkowski