- Freeradius-Users - lists.freeradius.org

eap_peap: ERROR: System call (I/O) error (-1)
by Arnaud LAURIOU 16 May '19

16 May '19

Hi, We are upgrading our freeradius servers : 3.0.19 (from packages.networkradius.com) under Ubuntu 18.04. Tests are good with most clients (linux, windows, mac) but fail with Android clients (version 7) with a EAP error message. The first EAP exchanges seem to work fine (sections 0 to 4) then fail in section 5. Here is the log : Ready to process requests (0) Received Access-Request Id 102 from 195.220.94.1:1645 to 194.57.4.197:1812 length 157 (0) User-Name = "anonymous(a)renater.fr" (0) Framed-MTU = 1400 (0) Called-Station-Id = "0012.d942.a460" (0) Calling-Station-Id = "ccc0.7942.6070" (0) Service-Type = Login-User (0) Message-Authenticator = 0xa0adc019dd45f629b627b8812b24032b (0) EAP-Message = 0x0201001901616e6f6e796d6f75734072656e617465722e6672 (0) NAS-Port-Type = Wireless-802.11 (0) NAS-Port = 314 (0) NAS-IP-Address = 195.220.94.1 (0) NAS-Identifier = "ap1000" (0) # Executing section authorize from file /etc/freeradius/sites-enabled/eduroam (0) authorize { (0) policy filter_username { (0) if (&User-Name) { (0) if (&User-Name) -> TRUE (0) if (&User-Name) { (0) if (&User-Name =~ / /) { (0) if (&User-Name =~ / /) -> FALSE (0) if (&User-Name =~ /@[^@]*@/ ) { (0) if (&User-Name =~ /@[^@]*@/ ) -> FALSE (0) if (&User-Name =~ /\.\./ ) { (0) if (&User-Name =~ /\.\./ ) -> FALSE (0) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { (0) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> FALSE (0) if (&User-Name =~ /\.$/) { (0) if (&User-Name =~ /\.$/) -> FALSE (0) if (&User-Name =~ /(a)\./) { (0) if (&User-Name =~ /(a)\./) -> FALSE (0) if (&User-Name !~ /(a)renater.fr/) { (0) if (&User-Name !~ /(a)renater.fr/) -> FALSE (0) } # if (&User-Name) = notfound (0) } # policy filter_username = notfound (0) if ("%{client:shortname}" !~ /rad[1-2]\.eduroam\.fr/) { (0) EXPAND %{client:shortname} (0) --> borne-rennes-1100 (0) if ("%{client:shortname}" !~ /rad[1-2]\.eduroam\.fr/) -> TRUE (0) if ("%{client:shortname}" !~ /rad[1-2]\.eduroam\.fr/) { (0) update request { (0) Operator-Name := "1renater.fr" (0) } # update request = noop (0) } # if ("%{client:shortname}" !~ /rad[1-2]\.eduroam\.fr/) = noop (0) policy cui.authorize { (0) if ("%{client:add_cui}" == 'yes') { (0) EXPAND %{client:add_cui} (0) --> yes (0) if ("%{client:add_cui}" == 'yes') -> TRUE (0) if ("%{client:add_cui}" == 'yes') { (0) update request { (0) &Chargeable-User-Identity := 0x00 (0) } # update request = noop (0) } # if ("%{client:add_cui}" == 'yes') = noop (0) } # policy cui.authorize = noop (0) auth_log: EXPAND /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d (0) auth_log: --> /var/log/freeradius/radacct/195.220.94.1/auth-detail-20190515 (0) auth_log: /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/195.220.94.1/auth-detail-20190515 (0) auth_log: EXPAND %t (0) auth_log: --> Wed May 15 10:01:24 2019 (0) [auth_log] = ok (0) suffix: Checking for suffix after "@" (0) suffix: Looking up realm "renater.fr" for User-Name = "anonymous(a)renater.fr" (0) suffix: Found realm "renater.fr" (0) suffix: Adding Realm = "renater.fr" (0) suffix: Authentication realm is LOCAL (0) [suffix] = ok (0) eap: Peer sent EAP Response (code 2) ID 1 length 25 (0) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize (0) [eap] = ok (0) } # authorize = ok (0) Found Auth-Type = eap (0) # Executing group from file /etc/freeradius/sites-enabled/eduroam (0) authenticate { (0) eap: Peer sent packet with method EAP Identity (1) (0) eap: Calling submodule eap_peap to process data (0) eap_peap: Initiating new TLS session (0) eap_peap: [eaptls start] = request (0) eap: Sending EAP Request (code 1) ID 2 length 6 (0) eap: EAP session adding &reply:State = 0xcaaa2a6ccaa833e7 (0) [eap] = handled (0) } # authenticate = handled (0) Using Post-Auth-Type Challenge (0) Post-Auth-Type sub-section not found. Ignoring. (0) # Executing group from file /etc/freeradius/sites-enabled/eduroam (0) Sent Access-Challenge Id 102 from 194.57.4.197:1812 to 195.220.94.1:1645 length 0 (0) EAP-Message = 0x010200061920 (0) Message-Authenticator = 0x00000000000000000000000000000000 (0) State = 0xcaaa2a6ccaa833e7ad7633b276a93937 (0) Finished request Waking up in 4.9 seconds. (1) Received Access-Request Id 103 from 195.220.94.1:1645 to 194.57.4.197:1812 length 317 (1) User-Name = "anonymous(a)renater.fr" (1) Framed-MTU = 1400 (1) Called-Station-Id = "0012.d942.a460" (1) Calling-Station-Id = "ccc0.7942.6070" (1) Service-Type = Login-User (1) Message-Authenticator = 0xb384c184c8fe45956c9246c04902dc31 (1) EAP-Message = 0x020200a719800000009d1603010098010000940303f94b22c62eeae3503df6f5e1bff784a2afda34d472918e62076ac43a07b9b3bc00003cc02bc02f009ec02cc030009fcca9cca8c009c023c013c02700330067c00ac024c014c0280039006bc007c011009c009d002f003c0035003d0005000a0100002fff0100010000170000000d0010000e0403040105030501060306010201000b00020100000a00080006001d00170018 (1) NAS-Port-Type = Wireless-802.11 (1) NAS-Port = 314 (1) State = 0xcaaa2a6ccaa833e7ad7633b276a93937 (1) NAS-IP-Address = 195.220.94.1 (1) NAS-Identifier = "ap1000" (1) session-state: No cached attributes (1) # Executing section authorize from file /etc/freeradius/sites-enabled/eduroam (1) authorize { (1) policy filter_username { (1) if (&User-Name) { (1) if (&User-Name) -> TRUE (1) if (&User-Name) { (1) if (&User-Name =~ / /) { (1) if (&User-Name =~ / /) -> FALSE (1) if (&User-Name =~ /@[^@]*@/ ) { (1) if (&User-Name =~ /@[^@]*@/ ) -> FALSE (1) if (&User-Name =~ /\.\./ ) { (1) if (&User-Name =~ /\.\./ ) -> FALSE (1) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { (1) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> FALSE (1) if (&User-Name =~ /\.$/) { (1) if (&User-Name =~ /\.$/) -> FALSE (1) if (&User-Name =~ /(a)\./) { (1) if (&User-Name =~ /(a)\./) -> FALSE (1) if (&User-Name !~ /(a)renater.fr/) { (1) if (&User-Name !~ /(a)renater.fr/) -> FALSE (1) } # if (&User-Name) = notfound (1) } # policy filter_username = notfound (1) if ("%{client:shortname}" !~ /rad[1-2]\.eduroam\.fr/) { (1) EXPAND %{client:shortname} (1) --> borne-rennes-1100 (1) if ("%{client:shortname}" !~ /rad[1-2]\.eduroam\.fr/) -> TRUE (1) if ("%{client:shortname}" !~ /rad[1-2]\.eduroam\.fr/) { (1) update request { (1) Operator-Name := "1renater.fr" (1) } # update request = noop (1) } # if ("%{client:shortname}" !~ /rad[1-2]\.eduroam\.fr/) = noop (1) policy cui.authorize { (1) if ("%{client:add_cui}" == 'yes') { (1) EXPAND %{client:add_cui} (1) --> yes (1) if ("%{client:add_cui}" == 'yes') -> TRUE (1) if ("%{client:add_cui}" == 'yes') { (1) update request { (1) &Chargeable-User-Identity := 0x00 (1) } # update request = noop (1) } # if ("%{client:add_cui}" == 'yes') = noop (1) } # policy cui.authorize = noop (1) auth_log: EXPAND /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d (1) auth_log: --> /var/log/freeradius/radacct/195.220.94.1/auth-detail-20190515 (1) auth_log: /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/195.220.94.1/auth-detail-20190515 (1) auth_log: EXPAND %t (1) auth_log: --> Wed May 15 10:01:24 2019 (1) [auth_log] = ok (1) suffix: Checking for suffix after "@" (1) suffix: Looking up realm "renater.fr" for User-Name = "anonymous(a)renater.fr" (1) suffix: Found realm "renater.fr" (1) suffix: Adding Realm = "renater.fr" (1) suffix: Authentication realm is LOCAL (1) [suffix] = ok (1) eap: Peer sent EAP Response (code 2) ID 2 length 167 (1) eap: Continuing tunnel setup (1) [eap] = ok (1) } # authorize = ok (1) Found Auth-Type = eap (1) # Executing group from file /etc/freeradius/sites-enabled/eduroam (1) authenticate { (1) eap: Expiring EAP session with state 0xcaaa2a6ccaa833e7 (1) eap: Finished EAP session with state 0xcaaa2a6ccaa833e7 (1) eap: Previous EAP request found for state 0xcaaa2a6ccaa833e7, released from the list (1) eap: Peer sent packet with method EAP PEAP (25) (1) eap: Calling submodule eap_peap to process data (1) eap_peap: Continuing EAP-TLS (1) eap_peap: Peer indicated complete TLS record size will be 157 bytes (1) eap_peap: Got complete TLS record (157 bytes) (1) eap_peap: [eaptls verify] = length included (1) eap_peap: (other): before SSL initialization (1) eap_peap: TLS_accept: before SSL initialization (1) eap_peap: TLS_accept: before SSL initialization (1) eap_peap: <<< recv TLS 1.2 [length 0098] (1) eap_peap: TLS_accept: SSLv3/TLS read client hello (1) eap_peap: >>> send TLS 1.2 [length 003d] (1) eap_peap: TLS_accept: SSLv3/TLS write server hello (1) eap_peap: >>> send TLS 1.2 [length 0c90] (1) eap_peap: TLS_accept: SSLv3/TLS write certificate (1) eap_peap: >>> send TLS 1.2 [length 014d] (1) eap_peap: TLS_accept: SSLv3/TLS write key exchange (1) eap_peap: >>> send TLS 1.2 [length 0004] (1) eap_peap: TLS_accept: SSLv3/TLS write server done (1) eap_peap: TLS_accept: Need to read more data: SSLv3/TLS write server done (1) eap_peap: TLS - In Handshake Phase (1) eap_peap: TLS - got 3634 bytes of data (1) eap_peap: [eaptls process] = handled (1) eap: Sending EAP Request (code 1) ID 3 length 1024 (1) eap: EAP session adding &reply:State = 0xcaaa2a6ccba933e7 (1) [eap] = handled (1) } # authenticate = handled (1) Using Post-Auth-Type Challenge (1) Post-Auth-Type sub-section not found. Ignoring. (1) # Executing group from file /etc/freeradius/sites-enabled/eduroam (1) Sent Access-Challenge Id 103 from 194.57.4.197:1812 to 195.220.94.1:1645 length 0 (1) EAP-Message = 0x0103040019c000000e32160303003d02000039030349a0e794e6bc9ac98b22c390967324e4711c255b0bafc92c5c0b74d1b437b35e00c02f000011ff01000100000b000403000102001700001603030c900b000c8c000c890007843082078030820668a00302010202100cf0c689f2b6db0e4f019ae302502e32300d06092a864886f70d01010b05003064310b3009060355040613024e4c311630140603550408130d4e6f6f72642d486f6c6c616e643112301006035504071309416d7374657264616d310f300d060355040a1306544552454e41311830160603550403130f544552454e412053534c2043412033301e170d3139303431363030303030305a170d3231303731393030303030305a30818f310b3009060355040613024652310e300c060355040713055061726973313f303d060355040a13365245532e204e41542e2044452054454c45434f4d2e20504f5552204c4120544543482e204420454e532e204554204c4120524543482e312f302d060355 (1) Message-Authenticator = 0x00000000000000000000000000000000 (1) State = 0xcaaa2a6ccba933e7ad7633b276a93937 (1) Finished request Waking up in 4.9 seconds. (2) Received Access-Request Id 104 from 195.220.94.1:1645 to 194.57.4.197:1812 length 156 (2) User-Name = "anonymous(a)renater.fr" (2) Framed-MTU = 1400 (2) Called-Station-Id = "0012.d942.a460" (2) Calling-Station-Id = "ccc0.7942.6070" (2) Service-Type = Login-User (2) Message-Authenticator = 0xc3b7d99ca284d8f861e93b8a9ecb97b8 (2) EAP-Message = 0x020300061900 (2) NAS-Port-Type = Wireless-802.11 (2) NAS-Port = 314 (2) State = 0xcaaa2a6ccba933e7ad7633b276a93937 (2) NAS-IP-Address = 195.220.94.1 (2) NAS-Identifier = "ap1000" (2) session-state: No cached attributes (2) # Executing section authorize from file /etc/freeradius/sites-enabled/eduroam (2) authorize { (2) policy filter_username { (2) if (&User-Name) { (2) if (&User-Name) -> TRUE (2) if (&User-Name) { (2) if (&User-Name =~ / /) { (2) if (&User-Name =~ / /) -> FALSE (2) if (&User-Name =~ /@[^@]*@/ ) { (2) if (&User-Name =~ /@[^@]*@/ ) -> FALSE (2) if (&User-Name =~ /\.\./ ) { (2) if (&User-Name =~ /\.\./ ) -> FALSE (2) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { (2) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> FALSE (2) if (&User-Name =~ /\.$/) { (2) if (&User-Name =~ /\.$/) -> FALSE (2) if (&User-Name =~ /(a)\./) { (2) if (&User-Name =~ /(a)\./) -> FALSE (2) if (&User-Name !~ /(a)renater.fr/) { (2) if (&User-Name !~ /(a)renater.fr/) -> FALSE (2) } # if (&User-Name) = notfound (2) } # policy filter_username = notfound (2) if ("%{client:shortname}" !~ /rad[1-2]\.eduroam\.fr/) { (2) EXPAND %{client:shortname} (2) --> borne-rennes-1100 (2) if ("%{client:shortname}" !~ /rad[1-2]\.eduroam\.fr/) -> TRUE (2) if ("%{client:shortname}" !~ /rad[1-2]\.eduroam\.fr/) { (2) update request { (2) Operator-Name := "1renater.fr" (2) } # update request = noop (2) } # if ("%{client:shortname}" !~ /rad[1-2]\.eduroam\.fr/) = noop (2) policy cui.authorize { (2) if ("%{client:add_cui}" == 'yes') { (2) EXPAND %{client:add_cui} (2) --> yes (2) if ("%{client:add_cui}" == 'yes') -> TRUE (2) if ("%{client:add_cui}" == 'yes') { (2) update request { (2) &Chargeable-User-Identity := 0x00 (2) } # update request = noop (2) } # if ("%{client:add_cui}" == 'yes') = noop (2) } # policy cui.authorize = noop (2) auth_log: EXPAND /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d (2) auth_log: --> /var/log/freeradius/radacct/195.220.94.1/auth-detail-20190515 (2) auth_log: /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/195.220.94.1/auth-detail-20190515 (2) auth_log: EXPAND %t (2) auth_log: --> Wed May 15 10:01:24 2019 (2) [auth_log] = ok (2) suffix: Checking for suffix after "@" (2) suffix: Looking up realm "renater.fr" for User-Name = "anonymous(a)renater.fr" (2) suffix: Found realm "renater.fr" (2) suffix: Adding Realm = "renater.fr" (2) suffix: Authentication realm is LOCAL (2) [suffix] = ok (2) eap: Peer sent EAP Response (code 2) ID 3 length 6 (2) eap: Continuing tunnel setup (2) [eap] = ok (2) } # authorize = ok (2) Found Auth-Type = eap (2) # Executing group from file /etc/freeradius/sites-enabled/eduroam (2) authenticate { (2) eap: Expiring EAP session with state 0xcaaa2a6ccba933e7 (2) eap: Finished EAP session with state 0xcaaa2a6ccba933e7 (2) eap: Previous EAP request found for state 0xcaaa2a6ccba933e7, released from the list (2) eap: Peer sent packet with method EAP PEAP (25) (2) eap: Calling submodule eap_peap to process data (2) eap_peap: Continuing EAP-TLS (2) eap_peap: Peer ACKed our handshake fragment (2) eap_peap: [eaptls verify] = request (2) eap_peap: [eaptls process] = handled (2) eap: Sending EAP Request (code 1) ID 4 length 1020 (2) eap: EAP session adding &reply:State = 0xcaaa2a6cc8ae33e7 (2) [eap] = handled (2) } # authenticate = handled (2) Using Post-Auth-Type Challenge (2) Post-Auth-Type sub-section not found. Ignoring. (2) # Executing group from file /etc/freeradius/sites-enabled/eduroam (2) Sent Access-Challenge Id 104 from 194.57.4.197:1812 to 195.220.94.1:1645 length 0 (2) EAP-Message = 0x010403fc1940332e63726c304c0603551d2004453043303706096086480186fd6c0101302a302806082b06010505070201161c68747470733a2f2f7777772e64696769636572742e636f6d2f4350533008060667810c010202306e06082b0601050507010104623060302406082b060105050730018618687474703a2f2f6f6373702e64696769636572742e636f6d303806082b06010505073002862c687474703a2f2f636163657274732e64696769636572742e636f6d2f544552454e4153534c4341332e637274300c0603551d130101ff04023000308201f6060a2b06010401d679020402048201e6048201e201e0007600ee4bbdb775ce60bae142691fabe19e66a30f7e5fb072d88300c47b897aa8fdcb0000016a268a5a9d000004030047304502201d5d5db28b56e2d37b6d45a00c9f7818066493c657cbb0bf6f03bc2683529e8c022100eeee46573a2cb109e769cb71924f257162c62983e5029ee9ff2420a62554f6430077008775bfe7597cf88c43995f (2) Message-Authenticator = 0x00000000000000000000000000000000 (2) State = 0xcaaa2a6cc8ae33e7ad7633b276a93937 (2) Finished request Waking up in 4.9 seconds. (3) Received Access-Request Id 105 from 195.220.94.1:1645 to 194.57.4.197:1812 length 156 (3) User-Name = "anonymous(a)renater.fr" (3) Framed-MTU = 1400 (3) Called-Station-Id = "0012.d942.a460" (3) Calling-Station-Id = "ccc0.7942.6070" (3) Service-Type = Login-User (3) Message-Authenticator = 0x0eec5ab7b19d608c9d73b4c13de1df93 (3) EAP-Message = 0x020400061900 (3) NAS-Port-Type = Wireless-802.11 (3) NAS-Port = 314 (3) State = 0xcaaa2a6cc8ae33e7ad7633b276a93937 (3) NAS-IP-Address = 195.220.94.1 (3) NAS-Identifier = "ap1000" (3) session-state: No cached attributes (3) # Executing section authorize from file /etc/freeradius/sites-enabled/eduroam (3) authorize { (3) policy filter_username { (3) if (&User-Name) { (3) if (&User-Name) -> TRUE (3) if (&User-Name) { (3) if (&User-Name =~ / /) { (3) if (&User-Name =~ / /) -> FALSE (3) if (&User-Name =~ /@[^@]*@/ ) { (3) if (&User-Name =~ /@[^@]*@/ ) -> FALSE (3) if (&User-Name =~ /\.\./ ) { (3) if (&User-Name =~ /\.\./ ) -> FALSE (3) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { (3) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> FALSE (3) if (&User-Name =~ /\.$/) { (3) if (&User-Name =~ /\.$/) -> FALSE (3) if (&User-Name =~ /(a)\./) { (3) if (&User-Name =~ /(a)\./) -> FALSE (3) if (&User-Name !~ /(a)renater.fr/) { (3) if (&User-Name !~ /(a)renater.fr/) -> FALSE (3) } # if (&User-Name) = notfound (3) } # policy filter_username = notfound (3) if ("%{client:shortname}" !~ /rad[1-2]\.eduroam\.fr/) { (3) EXPAND %{client:shortname} (3) --> borne-rennes-1100 (3) if ("%{client:shortname}" !~ /rad[1-2]\.eduroam\.fr/) -> TRUE (3) if ("%{client:shortname}" !~ /rad[1-2]\.eduroam\.fr/) { (3) update request { (3) Operator-Name := "1renater.fr" (3) } # update request = noop (3) } # if ("%{client:shortname}" !~ /rad[1-2]\.eduroam\.fr/) = noop (3) policy cui.authorize { (3) if ("%{client:add_cui}" == 'yes') { (3) EXPAND %{client:add_cui} (3) --> yes (3) if ("%{client:add_cui}" == 'yes') -> TRUE (3) if ("%{client:add_cui}" == 'yes') { (3) update request { (3) &Chargeable-User-Identity := 0x00 (3) } # update request = noop (3) } # if ("%{client:add_cui}" == 'yes') = noop (3) } # policy cui.authorize = noop (3) auth_log: EXPAND /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d (3) auth_log: --> /var/log/freeradius/radacct/195.220.94.1/auth-detail-20190515 (3) auth_log: /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/195.220.94.1/auth-detail-20190515 (3) auth_log: EXPAND %t (3) auth_log: --> Wed May 15 10:01:24 2019 (3) [auth_log] = ok (3) suffix: Checking for suffix after "@" (3) suffix: Looking up realm "renater.fr" for User-Name = "anonymous(a)renater.fr" (3) suffix: Found realm "renater.fr" (3) suffix: Adding Realm = "renater.fr" (3) suffix: Authentication realm is LOCAL (3) [suffix] = ok (3) eap: Peer sent EAP Response (code 2) ID 4 length 6 (3) eap: Continuing tunnel setup (3) [eap] = ok (3) } # authorize = ok (3) Found Auth-Type = eap (3) # Executing group from file /etc/freeradius/sites-enabled/eduroam (3) authenticate { (3) eap: Expiring EAP session with state 0xcaaa2a6cc8ae33e7 (3) eap: Finished EAP session with state 0xcaaa2a6cc8ae33e7 (3) eap: Previous EAP request found for state 0xcaaa2a6cc8ae33e7, released from the list (3) eap: Peer sent packet with method EAP PEAP (25) (3) eap: Calling submodule eap_peap to process data (3) eap_peap: Continuing EAP-TLS (3) eap_peap: Peer ACKed our handshake fragment (3) eap_peap: [eaptls verify] = request (3) eap_peap: [eaptls process] = handled (3) eap: Sending EAP Request (code 1) ID 5 length 1020 (3) eap: EAP session adding &reply:State = 0xcaaa2a6cc9af33e7 (3) [eap] = handled (3) } # authenticate = handled (3) Using Post-Auth-Type Challenge (3) Post-Auth-Type sub-section not found. Ignoring. (3) # Executing group from file /etc/freeradius/sites-enabled/eduroam (3) Sent Access-Challenge Id 105 from 194.57.4.197:1812 to 195.220.94.1:1645 length 0 (3) EAP-Message = 0x010503fc19403fdb959a91cb6aeeefe465300d06092a864886f70d01010b05003065310b300906035504061302555331153013060355040a130c446967694365727420496e6331193017060355040b13107777772e64696769636572742e636f6d312430220603550403131b4469676943657274204173737572656420494420526f6f74204341301e170d3134313131383132303030305a170d3234313131383132303030305a3064310b3009060355040613024e4c311630140603550408130d4e6f6f72642d486f6c6c616e643112301006035504071309416d7374657264616d310f300d060355040a1306544552454e41311830160603550403130f544552454e412053534c204341203330820122300d06092a864886f70d01010105000382010f003082010a0282010100c5760f0fd943293b6c6dd147adde10bf23c278a84a7735f1235be04c1e41e7c23100bd88374575ddb90210801e8fed64230445a7a0393b814dcf633fc249ff229e88b0d296b95c8a74 (3) Message-Authenticator = 0x00000000000000000000000000000000 (3) State = 0xcaaa2a6cc9af33e7ad7633b276a93937 (3) Finished request Waking up in 4.9 seconds. (4) Received Access-Request Id 106 from 195.220.94.1:1645 to 194.57.4.197:1812 length 156 (4) User-Name = "anonymous(a)renater.fr" (4) Framed-MTU = 1400 (4) Called-Station-Id = "0012.d942.a460" (4) Calling-Station-Id = "ccc0.7942.6070" (4) Service-Type = Login-User (4) Message-Authenticator = 0xd94cb1d71dbe58181bc61743c36af928 (4) EAP-Message = 0x020500061900 (4) NAS-Port-Type = Wireless-802.11 (4) NAS-Port = 314 (4) State = 0xcaaa2a6cc9af33e7ad7633b276a93937 (4) NAS-IP-Address = 195.220.94.1 (4) NAS-Identifier = "ap1000" (4) session-state: No cached attributes (4) # Executing section authorize from file /etc/freeradius/sites-enabled/eduroam (4) authorize { (4) policy filter_username { (4) if (&User-Name) { (4) if (&User-Name) -> TRUE (4) if (&User-Name) { (4) if (&User-Name =~ / /) { (4) if (&User-Name =~ / /) -> FALSE (4) if (&User-Name =~ /@[^@]*@/ ) { (4) if (&User-Name =~ /@[^@]*@/ ) -> FALSE (4) if (&User-Name =~ /\.\./ ) { (4) if (&User-Name =~ /\.\./ ) -> FALSE (4) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { (4) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> FALSE (4) if (&User-Name =~ /\.$/) { (4) if (&User-Name =~ /\.$/) -> FALSE (4) if (&User-Name =~ /(a)\./) { (4) if (&User-Name =~ /(a)\./) -> FALSE (4) if (&User-Name !~ /(a)renater.fr/) { (4) if (&User-Name !~ /(a)renater.fr/) -> FALSE (4) } # if (&User-Name) = notfound (4) } # policy filter_username = notfound (4) if ("%{client:shortname}" !~ /rad[1-2]\.eduroam\.fr/) { (4) EXPAND %{client:shortname} (4) --> borne-rennes-1100 (4) if ("%{client:shortname}" !~ /rad[1-2]\.eduroam\.fr/) -> TRUE (4) if ("%{client:shortname}" !~ /rad[1-2]\.eduroam\.fr/) { (4) update request { (4) Operator-Name := "1renater.fr" (4) } # update request = noop (4) } # if ("%{client:shortname}" !~ /rad[1-2]\.eduroam\.fr/) = noop (4) policy cui.authorize { (4) if ("%{client:add_cui}" == 'yes') { (4) EXPAND %{client:add_cui} (4) --> yes (4) if ("%{client:add_cui}" == 'yes') -> TRUE (4) if ("%{client:add_cui}" == 'yes') { (4) update request { (4) &Chargeable-User-Identity := 0x00 (4) } # update request = noop (4) } # if ("%{client:add_cui}" == 'yes') = noop (4) } # policy cui.authorize = noop (4) auth_log: EXPAND /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d (4) auth_log: --> /var/log/freeradius/radacct/195.220.94.1/auth-detail-20190515 (4) auth_log: /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/195.220.94.1/auth-detail-20190515 (4) auth_log: EXPAND %t (4) auth_log: --> Wed May 15 10:01:24 2019 (4) [auth_log] = ok (4) suffix: Checking for suffix after "@" (4) suffix: Looking up realm "renater.fr" for User-Name = "anonymous(a)renater.fr" (4) suffix: Found realm "renater.fr" (4) suffix: Adding Realm = "renater.fr" (4) suffix: Authentication realm is LOCAL (4) [suffix] = ok (4) eap: Peer sent EAP Response (code 2) ID 5 length 6 (4) eap: Continuing tunnel setup (4) [eap] = ok (4) } # authorize = ok (4) Found Auth-Type = eap (4) # Executing group from file /etc/freeradius/sites-enabled/eduroam (4) authenticate { (4) eap: Expiring EAP session with state 0xcaaa2a6cc9af33e7 (4) eap: Finished EAP session with state 0xcaaa2a6cc9af33e7 (4) eap: Previous EAP request found for state 0xcaaa2a6cc9af33e7, released from the list (4) eap: Peer sent packet with method EAP PEAP (25) (4) eap: Calling submodule eap_peap to process data (4) eap_peap: Continuing EAP-TLS (4) eap_peap: Peer ACKed our handshake fragment (4) eap_peap: [eaptls verify] = request (4) eap_peap: [eaptls process] = handled (4) eap: Sending EAP Request (code 1) ID 6 length 598 (4) eap: EAP session adding &reply:State = 0xcaaa2a6cceac33e7 (4) [eap] = handled (4) } # authenticate = handled (4) Using Post-Auth-Type Challenge (4) Post-Auth-Type sub-section not found. Ignoring. (4) # Executing group from file /etc/freeradius/sites-enabled/eduroam (4) Sent Access-Challenge Id 106 from 194.57.4.197:1812 to 195.220.94.1:1645 length 0 (4) EAP-Message = 0x01060256190098cf27364f11327474e640dd1dcdf2687735afb38c5dc604bf15f423678bb96f9704eb469dc2cdc9d1a4ae812ec9bab1e880d01cc939c15676596c9c7de3a9f0d3d134d83c49598b1a98cebfc6f2d83035ffe96f5da0af3aee6653aeaa8c69c8be9aa7a07bd8824b3313c807f377d7f364cd9e63f9422753ae103389723715f1bef71e35a2cec32df2d7b2e60bc769c0e51f5f7c699b7ece261a3344c3ba77053bba5d3f4189fa163bee046e5bac564bef8c70f24a7b57bd196e8b360754262d8609941f5f37abf0233f8f2c5f969e4771a844dea9b9852fb53460a55f09a09a431dd4bf2d44d68ddafd75cb5f16a00e61c2703d36160303014d0c0001490300174104338c12bd74ede52c52ca7f42320ec6f8b6504ffbee03cf64072b00d86733e5bdd64ad52a632dc45754243f5aeb2a255f98aaf93eed501786b8ec1e063e791ff104010100a09b99efec1da8d887c2b04a9f2085dd42d2880a6265447194091665e1c7f159b7aeea5e0217e455b641 (4) Message-Authenticator = 0x00000000000000000000000000000000 (4) State = 0xcaaa2a6cceac33e7ad7633b276a93937 (4) Finished request Waking up in 4.9 seconds. (5) Received Access-Request Id 107 from 195.220.94.1:1645 to 194.57.4.197:1812 length 167 (5) User-Name = "anonymous(a)renater.fr" (5) Framed-MTU = 1400 (5) Called-Station-Id = "0012.d942.a460" (5) Calling-Station-Id = "ccc0.7942.6070" (5) Service-Type = Login-User (5) Message-Authenticator = 0xd4447da78b6f5e04c59616dc33ec3fbe (5) EAP-Message = 0x0206001119800000000715030300020250 (5) NAS-Port-Type = Wireless-802.11 (5) NAS-Port = 314 (5) State = 0xcaaa2a6cceac33e7ad7633b276a93937 (5) NAS-IP-Address = 195.220.94.1 (5) NAS-Identifier = "ap1000" (5) session-state: No cached attributes (5) # Executing section authorize from file /etc/freeradius/sites-enabled/eduroam (5) authorize { (5) policy filter_username { (5) if (&User-Name) { (5) if (&User-Name) -> TRUE (5) if (&User-Name) { (5) if (&User-Name =~ / /) { (5) if (&User-Name =~ / /) -> FALSE (5) if (&User-Name =~ /@[^@]*@/ ) { (5) if (&User-Name =~ /@[^@]*@/ ) -> FALSE (5) if (&User-Name =~ /\.\./ ) { (5) if (&User-Name =~ /\.\./ ) -> FALSE (5) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { (5) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> FALSE (5) if (&User-Name =~ /\.$/) { (5) if (&User-Name =~ /\.$/) -> FALSE (5) if (&User-Name =~ /(a)\./) { (5) if (&User-Name =~ /(a)\./) -> FALSE (5) if (&User-Name !~ /(a)renater.fr/) { (5) if (&User-Name !~ /(a)renater.fr/) -> FALSE (5) } # if (&User-Name) = notfound (5) } # policy filter_username = notfound (5) if ("%{client:shortname}" !~ /rad[1-2]\.eduroam\.fr/) { (5) EXPAND %{client:shortname} (5) --> borne-rennes-1100 (5) if ("%{client:shortname}" !~ /rad[1-2]\.eduroam\.fr/) -> TRUE (5) if ("%{client:shortname}" !~ /rad[1-2]\.eduroam\.fr/) { (5) update request { (5) Operator-Name := "1renater.fr" (5) } # update request = noop (5) } # if ("%{client:shortname}" !~ /rad[1-2]\.eduroam\.fr/) = noop (5) policy cui.authorize { (5) if ("%{client:add_cui}" == 'yes') { (5) EXPAND %{client:add_cui} (5) --> yes (5) if ("%{client:add_cui}" == 'yes') -> TRUE (5) if ("%{client:add_cui}" == 'yes') { (5) update request { (5) &Chargeable-User-Identity := 0x00 (5) } # update request = noop (5) } # if ("%{client:add_cui}" == 'yes') = noop (5) } # policy cui.authorize = noop (5) auth_log: EXPAND /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d (5) auth_log: --> /var/log/freeradius/radacct/195.220.94.1/auth-detail-20190515 (5) auth_log: /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/freeradius/radacct/195.220.94.1/auth-detail-20190515 (5) auth_log: EXPAND %t (5) auth_log: --> Wed May 15 10:01:24 2019 (5) [auth_log] = ok (5) suffix: Checking for suffix after "@" (5) suffix: Looking up realm "renater.fr" for User-Name = "anonymous(a)renater.fr" (5) suffix: Found realm "renater.fr" (5) suffix: Adding Realm = "renater.fr" (5) suffix: Authentication realm is LOCAL (5) [suffix] = ok (5) eap: Peer sent EAP Response (code 2) ID 6 length 17 (5) eap: Continuing tunnel setup (5) [eap] = ok (5) } # authorize = ok (5) Found Auth-Type = eap (5) # Executing group from file /etc/freeradius/sites-enabled/eduroam (5) authenticate { (5) eap: Expiring EAP session with state 0xcaaa2a6cceac33e7 (5) eap: Finished EAP session with state 0xcaaa2a6cceac33e7 (5) eap: Previous EAP request found for state 0xcaaa2a6cceac33e7, released from the list (5) eap: Peer sent packet with method EAP PEAP (25) (5) eap: Calling submodule eap_peap to process data (5) eap_peap: Continuing EAP-TLS (5) eap_peap: Peer indicated complete TLS record size will be 7 bytes (5) eap_peap: Got complete TLS record (7 bytes) (5) eap_peap: [eaptls verify] = length included (5) eap_peap: <<< recv TLS 1.2 [length 0002] (5) eap_peap: ERROR: TLS Alert read:fatal:internal error (5) eap_peap: TLS_accept: Need to read more data: SSLv3/TLS write server done (5) eap_peap: ERROR: Failed in __FUNCTION__ (SSL_read): error:14094438:SSL routines:ssl3_read_bytes:tlsv1 alert internal error (5) eap_peap: ERROR: System call (I/O) error (-1) (5) eap_peap: ERROR: TLS receive handshake failed during operation (5) eap_peap: ERROR: [eaptls process] = fail (5) eap: ERROR: Failed continuing EAP PEAP (25) session. EAP sub-module failed (5) eap: Sending EAP Failure (code 4) ID 6 length 4 (5) eap: Failed in EAP select (5) [eap] = invalid (5) } # authenticate = invalid (5) Failed to authenticate the user (5) Using Post-Auth-Type Reject (5) # Executing group from file /etc/freeradius/sites-enabled/eduroam (5) Post-Auth-Type REJECT { (5) reply_log: EXPAND /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/reply-detail-%Y%m%d (5) reply_log: --> /var/log/freeradius/radacct/195.220.94.1/reply-detail-20190515 (5) reply_log: /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/reply-detail-%Y%m%d expands to /var/log/freeradius/radacct/195.220.94.1/reply-detail-20190515 (5) reply_log: EXPAND %t (5) reply_log: --> Wed May 15 10:01:24 2019 (5) [reply_log] = ok (5) eduroam_cui_log: EXPAND eduroam_log.%{%{reply:Packet-Type}:-format} (5) eduroam_cui_log: --> eduroam_log.Access-Reject (5) eduroam_cui_log: EXPAND %t : eduroam-auth#ORG=%{request:Realm}#USER=%{User-Name}#CSI=%{%{Calling-Station-Id}:-Unknown Caller Id}#NAS=%{%{Called-Station-Id}:-Unknown Access Point}#CUI=%{%{reply:Chargeable-User-Identity}:-Unknown}#MSG=%{%{reply:Reply-Message}:-No Failure Reason}#RESULT=FAIL# (5) eduroam_cui_log: --> Wed May 15 10:01:24 2019 : eduroam-auth#ORG=renater.fr#USER=anonymous@renater.fr#CSI=ccc0.7942.6070#NAS=0012.d942.a460#CUI=Unknown#MSG=No Failure Reason#RESULT=FAIL# (5) eduroam_cui_log: EXPAND /var/log/freeradius/radius.log (5) eduroam_cui_log: --> /var/log/freeradius/radius.log (5) [eduroam_cui_log] = ok (5) } # Post-Auth-Type REJECT = ok (5) Login incorrect (eap_peap: TLS Alert read:fatal:internal error): [anonymous(a)renater.fr] (from client borne-rennes-1100 port 314 cli ccc0.7942.6070) (5) Sent Access-Reject Id 107 from 194.57.4.197:1812 to 195.220.94.1:1645 length 0 (5) EAP-Message = 0x04060004 (5) Message-Authenticator = 0x00000000000000000000000000000000 (5) Finished request Any idea how to correct this error ? Regards, Arnaud Lauriou

1 1

systemd watchdog start-up not working correctly on Sabayon/Gentoo
by Daniele Rondina 16 May '19

16 May '19

Hi, I follow "systemctl start-up not working correctly" thread because I'm trying to integrate systemd watchdog support to Gentoo/Sabayon distro. Currently, I'm testing Freeradius v3.0.x-HEAD with systemd-239 but it seems that notifications returned to systemd aren't correct. # systemctl --version systemd 239 +PAM -AUDIT -SELINUX +IMA -APPARMOR +SMACK -SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT -GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID -ELFUTILS +KMOD -IDN2 -IDN +PCRE2 default-hierarchy=hybrid # radiusd -v radiusd: FreeRADIUS Version 3.0.20 (git #136ba4541), for host x86_64- pc-linux-gnu, built on May 13 2019 at 16:31:56 FreeRADIUS Version 3.0.20 Copyright (C) 1999-2019 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 >From systemctl log I see that watchdog notification are returned by freeradius server but probably are wrong because service receive timeout. May 13 19:51:35 radius radiusd[8093]: Mon May 13 19:51:35 2019 : Debug: Waking up in 29.6 seconds. May 13 19:52:04 radius radiusd[8093]: Mon May 13 19:52:04 2019 : Debug: Emitting systemd watchdog notification May 13 19:52:04 radius radiusd[8093]: Mon May 13 19:52:04 2019 : Debug: Waking up in 29.9 seconds. May 13 19:52:34 radius radiusd[8093]: Mon May 13 19:52:34 2019 : Debug: Emitting systemd watchdog notification May 13 19:52:34 radius radiusd[8093]: Mon May 13 19:52:34 2019 : Debug: Waking up in 29.9 seconds. May 13 19:53:04 radius radiusd[8093]: Mon May 13 19:53:04 2019 : Debug: Emitting systemd watchdog notification May 13 19:53:04 radius radiusd[8093]: Mon May 13 19:53:04 2019 : Debug: Waking up in 29.9 seconds. May 13 19:53:04 radius radiusd[8093]: Mon May 13 19:53:04 2019 : Info: Signalled to terminate May 13 19:53:04 radius systemd[1]: freeradius.service: Start operation timed out. Terminating. May 13 19:53:04 radius systemd[1]: freeradius.service: Failed with result 'timeout'. May 13 19:53:04 radius systemd[1]: Failed to start FreeRADIUS Server. I will try to investigate better in the next days also with systemd v.242. -- geaaru

3 5

rediswho and date timestamps
by Mike Lopes 15 May '19

15 May '19

Hi, I'm in the process of updating our radius servers from 3.0.3 to 3.0.18 and I can't seem to get the unix timestamps into redis the way it is currently done. Currently my configuration is like this: start-insert = "LPUSH logs|%{User-Name} %{Event-Timestamp#}, ... On the new servers I'm building, Seems like that changed in the current version freeradius. I've been over the documentation and read the configuration files to no avail. I have tried to use date module, I have tried to use %S and %T from reading a few threads on this list but it keeps failing to convert into unix time.. I've tried this in the preacct section: update request { &Event-Timestamp := "%{date:%{Event-Timestamp}}" } Can someone point me to the # equivalent to get conversion to unix time? Thanks. -Mike

2 2

SQL query as fallback to auth script?
by Wladyslaw Jankowski 14 May '19

14 May '19

Hi list! This issue was probably already answered but I cannot find it. I have a setup where FreeRADIUS can't have access to the database where NT hashes are stored. I would like FreeRADIUS to fire up a script and than fallback to SQL. This way I could at least temporarily grab the hash to local database with the script, script would "Reject", and FreeRADIUS would fall back to local SQL where the hash temporarily exists. After all the EAP magic - FreeRADIUS would try authorize the user via local database. This is a VPN (not NAS, WiFi..) setup that for best compatibility with most operating systems would use EAP-MSCHAPv2 or EAP-TTLS but in any case - server is not receiving plaintext password from the user (like with PAP) so I can't pass it to the script. I have tried the following configuration, but the only SQL queries fired after script "Rejects" the user are INSERTS logging this failure: authorize { filter_username preprocess auth_log mschap digest expiration logintime eap pap update control { Auth-Type := `/bin/python /scripts/radiusauth.py '%{User-Name}' 'rejectme'` } if (fail) { sql } } Please find the log below. (2) Received Access-Request Id 197 from 127.0.0.1:28318 to 127.0.0.1:1812 length 144 (2) User-Name = "provided-username" (2) NAS-Port-Type = Virtual (2) Service-Type = Framed-User (2) NAS-Port = 35 (2) NAS-Port-Id = "IKEv2" (2) NAS-IP-Address = server-public-ip (2) Called-Station-Id = "server-public-ip[4500]" (2) Calling-Station-Id = "client-public-ip[60403]" (2) EAP-Message = 0x0200000a0121349a (2) NAS-Identifier = "vpn-software" (2) Message-Authenticator = 0xa123abc123abc123abc123abc123abc1 (2) # Executing section authorize from file /etc/raddb/sites-enabled/default (2) authorize { (2) policy filter_username { (2) if (&User-Name) { (2) if (&User-Name) -> TRUE (2) if (&User-Name) { (2) if (&User-Name =~ / /) { (2) if (&User-Name =~ / /) -> FALSE (2) if (&User-Name =~ /@[^@]*@/ ) { (2) if (&User-Name =~ /@[^@]*@/ ) -> FALSE (2) if (&User-Name =~ /\.\./ ) { (2) if (&User-Name =~ /\.\./ ) -> FALSE (2) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { (2) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> FALSE (2) if (&User-Name =~ /\.$/) { (2) if (&User-Name =~ /\.$/) -> FALSE (2) if (&User-Name =~ /(a)\./) { (2) if (&User-Name =~ /(a)\./) -> FALSE (2) } # if (&User-Name) = notfound (2) } # policy filter_username = notfound (2) [preprocess] = ok (2) auth_log: EXPAND /var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d (2) auth_log: --> /var/log/radacct/127.0.0.1/auth-detail-20190503 (2) auth_log: /var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radacct/127.0.0.1/auth-detail-20190503 (2) auth_log: EXPAND %t (2) auth_log: --> Fri May 3 07:11:31 2019 (2) [auth_log] = ok (2) [chap] = noop (2) [mschap] = noop (2) [digest] = noop (2) [expiration] = noop (2) [logintime] = noop (2) eap: Peer sent EAP Response (code 2) ID 0 length 10 (2) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize (2) [eap] = ok (2) pap: WARNING: No "known good" password found for the user. Not setting Auth-Type (2) pap: WARNING: Authentication will fail unless a "known good" password is available (2) [pap] = noop (2) update control { (2) Executing: /bin/python /scripts/radiusauth.py '%{User-Name}' 'rejectme': (2) EXPAND %{User-Name} (2) --> provided-username (2) ERROR: Program returned code (1) and output 'Reject' (2) } # update control = fail (2) } # authorize = fail (2) Invalid user (Program returned code (1) and output 'Reject'): [provided-username/<via Auth-Type = eap>] (from client localhost port 35 cli client-public-ip[60403]) (2) Using Post-Auth-Type Reject (2) # Executing group from file /etc/raddb/sites-enabled/default (2) Post-Auth-Type REJECT { (2) sql: EXPAND .query (2) sql: --> .query (2) sql: Using query template 'query' rlm_sql (sql): Closing connection (6): Hit idle_timeout, was idle for 5679 seconds rlm_sql (sql): You probably need to lower "min" rlm_sql (sql): Closing connection (7): Hit idle_timeout, was idle for 5679 seconds rlm_sql (sql): You probably need to lower "min" rlm_sql (sql): 0 of 0 connections in use. You may need to increase "spare" rlm_sql (sql): Opening additional connection (8), 1 of 32 pending slots used rlm_sql (sql): Reserved connection (8) (2) sql: EXPAND %{User-Name} (2) sql: --> provided-username (2) sql: SQL-User-Name set to 'provided-username' (2) sql: EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') (2) sql: --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'provided-username', '', 'Access-Reject', '2019-05-03 07:11:31') (2) sql: Executing query: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'provided-username', '', 'Access-Reject', '2019-05-03 07:11:31') (2) sql: SQL query returned: success (2) sql: 1 record(s) updated rlm_sql (sql): Released connection (8) Need 2 more connections to reach min connections (3) rlm_sql (sql): Opening additional connection (9), 1 of 31 pending slots used (2) [sql] = ok (2) attr_filter.access_reject: EXPAND %{User-Name} (2) attr_filter.access_reject: --> provided-username (2) attr_filter.access_reject: Matched entry DEFAULT at line 11 (2) [attr_filter.access_reject] = updated (2) eap: Request was previously rejected, inserting EAP-Failure (2) eap: Sending EAP Failure (code 4) ID 0 length 4 (2) [eap] = updated (2) } # Post-Auth-Type REJECT = updated (2) Login incorrect (Program returned code (1) and output 'Reject'): [provided-username/<via Auth-Type = eap>] (from client localhost port 35 cli client-public-ip[60403]) (2) Delaying response for 1.000000 seconds Waking up in 0.9 seconds. (2) Sending delayed response (2) Sent Access-Reject Id 197 from 127.0.0.1:1812 to 127.0.0.1:28318 length 44 (2) EAP-Message = 0x04000004 (2) Message-Authenticator = 0x00000000000000000000000000000000 Waking up in 3.9 seconds. (2) Cleaning up request packet ID 197 with timestamp +6729 Ready to process requests TIA and apologies again if the question was already answered.

3 6

rlm_yubikey OTP + LDAP
by cbandara 14 May '19

14 May '19

Hi I am trying to implement a freeradius solution for a firewall. i cant find documentation on how to configure yubikeys OTP with ldap. i am getting some errors with my config. trying to see if there is good documentation out there Thanks rlm_ldap (ldap): Released connection (6) (0) files: users: Matched entry DEFAULT at line 13 (0) [files] = ok (0) yubikey: &request:Yubikey-OTP := <<< secret >>> (0) yubikey: &request:User-Password := <<< secret >>> (0) [yubikey] = ok (0) if (ok) { (0) if (ok) -> TRUE (0) if (ok) { (0) update control { (0) Auth-Type := yubikey (0) } # update control = noop (0) } # if (ok) = noop (0) } # authorize = ok (0) Found Auth-Type = yubikey (0) Found Auth-Type = yubikey (0) ERROR: Warning: Found 2 auth-types on request for user 'chula' (0) # Executing group from file /etc/raddb/sites-enabled/default (0) Auth-Type yubikey { (0) [yubikey] = noop (0) update request { (0) User-Password := Yubikey-Public-ID -> 'cccccckirnie' (0) } # update request = noop rlm_ldap (ldap): Reserved connection (5) (0) ldap: Login attempt by "chula" (0) ldap: Using user DN from request "cn=chula,ou=users,dc=xxxx,dc=yyyy" (0) ldap: Waiting for bind result... (0) ldap: ERROR: Bind credentials incorrect: Invalid credentials rlm_ldap (ldap): Released connection (5) (0) [ldap] = reject (0) } # Auth-Type yubikey = reject (0) Failed to authenticate the user (0) Using Post-Auth-Type Reject (0) Post-Auth-Type sub-section not found. Ignoring. (0) # Executing group from file /etc/raddb/sites-enabled/default Sent with [ProtonMail](https://protonmail.com) Secure Email.

2 1

Maximum number of lines in authorize file
by Gianni Costanzi 14 May '19

14 May '19

Hi, is there a maximum number of lines or "blocks" that can be defined in authorize (old users) file? Best regards, Gianni Costanzi

2 2

Freeradius on AWS ECS Fargate problem to authenticate using EAP-PEAP (MSCHAPv2) - Reading winbind reply failed! (0xc0000001)
by Antonio Castillo 13 May '19

13 May '19

Hello all!, I am trying to use Freeradius to authenticate our wifi clients against AWS Simple AD server using EAP-PEAP (MSCHAPv2) The tricky part is that I'm trying to run Freeradius in a AWS ECS Fargate service container. I'm using the Freeradius Docker Hub image: https://hub.docker.com/r/freeradius/freeradius-server Container OS version: root@b17cc3ba869c:/etc/freeradius# cat /etc/*release DISTRIB_ID=Ubuntu DISTRIB_RELEASE=18.04 I have a test EC2 instance running Freeradius that it's working fine, I can connect to the WiFi network using my Simple AD credentials with no issues. I built this test EC2 box to know exactly what needs to be done in order to use Freeradius for authentication and add the necessary steps to the Dockerfile for the Freeradius container. On Fargate, the problem seems to be caused by winbind On EC2, winbind works just fine. This is the winbind error: Mon May 13 17:06:00 2019 : ERROR: (3) mschap: Program returned code (1) and output 'Reading winbind reply failed! (0xc0000001)' Mon May 13 17:06:00 2019 : ERROR: (3) mschap: Reading winbind reply failed! (0xc0000001) Mon May 13 17:06:00 2019 : Debug: (3) mschap: Authentication failed (full freeradius debug log added at the end of this email) radtest works fine for pap: $ radtest antonio '<MY_PASSWORD>' 10.0.153.139 0 <MY_SECRET> Sent Access-Request Id 88 from 0.0.0.0:61601 to 10.0.153.139:1812 length 77 User-Name = "antonio" User-Password = "<MY_PASSWORD>" NAS-IP-Address = 127.0.0.1 NAS-Port = 0 Message-Authenticator = 0x00 Cleartext-Password = "<MY_PASSWORD>" Received Access-Accept Id 88 from 10.0.153.139:1812 to 172.16.0.54:61601 length 36 Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = "10" but it fails with mschap: $ radtest -t mschap antonio '<MY_PASSWORD>' 10.0.153.139 0 <MY_SECRET> Sent Access-Request Id 7 from 0.0.0.0:61367 to 10.0.153.139:1812 length 133 User-Name = "antonio" MS-CHAP-Password = "<MY_PASSWORD>" NAS-IP-Address = 127.0.0.1 NAS-Port = 0 Message-Authenticator = 0x00 Cleartext-Password = "<MY_PASSWORD>" MS-CHAP-Challenge = 0x2e3ecfc58cff680f MS-CHAP-Response = 0x0001000000000000000000000000000000000000000000000000c067bb42d3a35102436e299186f135f6f664ea811f2a148f Received Access-Reject Id 7 from 10.0.153.139:1812 to 172.16.0.54:61367 length 77 Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = "10" MS-CHAP-Error = "\000E=691 R=1 C=ed4c6cae95574d22 V=2" (0) -: Expected Access-Accept got Access-Reject I have added the 'freerad' user to the 'winbindd_priv' group and changed the permissions to 'root:winbindd_priv' on /var/lib/samba/winbindd_privileged/ as someone suggested on this link: https://xenomorph.net/linux/samba/issues/exec-program-output-reading-winbin… Also added some debugging lines to confirm that in fact the permissions and group changes are taking place and they did. Could it be that winbind wasn't made to be executed in a docker container? As I mentioned before, Freeradius is working fine when running on an EC2 instance, it runs fine in a docker container too, but winbind fails when running in a container. Any ideas? Thank you. Regards, Tono Here are the logs when trying to authenticate using mschap with radtest from my laptop. from /var/log/freeradius/radius.log in debug mode: Mon May 13 17:06:00 2019 : Debug: (3) Received Access-Request Id 7 from 10.0.0.191:61367 to 10.0.153.139:1812 length 133 Mon May 13 17:06:00 2019 : Debug: (3) User-Name = "antonio" Mon May 13 17:06:00 2019 : Debug: (3) NAS-IP-Address = 127.0.0.1 Mon May 13 17:06:00 2019 : Debug: (3) NAS-Port = 0 Mon May 13 17:06:00 2019 : Debug: (3) Message-Authenticator = 0xc70ca8663c85700b5a484bcd4cd5931d Mon May 13 17:06:00 2019 : Debug: (3) MS-CHAP-Challenge = 0x2e3ecfc58cff680f Mon May 13 17:06:00 2019 : Debug: (3) MS-CHAP-Response = 0x0001000000000000000000000000000000000000000000000000c067bb42d3a35102436e299186f135f6f664ea811f2a148f Mon May 13 17:06:00 2019 : Debug: (3) session-state: No State attribute Mon May 13 17:06:00 2019 : Debug: (3) # Executing section authorize from file /etc/freeradius/sites-enabled/default Mon May 13 17:06:00 2019 : Debug: (3) authorize { Mon May 13 17:06:00 2019 : Debug: (3) policy filter_username { Mon May 13 17:06:00 2019 : Debug: (3) if (&User-Name) { Mon May 13 17:06:00 2019 : Debug: (3) if (&User-Name) -> TRUE Mon May 13 17:06:00 2019 : Debug: (3) if (&User-Name) { Mon May 13 17:06:00 2019 : Debug: (3) if (&User-Name =~ / /) { Mon May 13 17:06:00 2019 : Debug: (3) if (&User-Name =~ / /) -> FALSE Mon May 13 17:06:00 2019 : Debug: (3) if (&User-Name =~ /@[^@]*@/ ) { Mon May 13 17:06:00 2019 : Debug: (3) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Mon May 13 17:06:00 2019 : Debug: (3) if (&User-Name =~ /\.\./ ) { Mon May 13 17:06:00 2019 : Debug: (3) if (&User-Name =~ /\.\./ ) -> FALSE Mon May 13 17:06:00 2019 : Debug: (3) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { Mon May 13 17:06:00 2019 : Debug: (3) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> FALSE Mon May 13 17:06:00 2019 : Debug: (3) if (&User-Name =~ /\.$/) { Mon May 13 17:06:00 2019 : Debug: (3) if (&User-Name =~ /\.$/) -> FALSE Mon May 13 17:06:00 2019 : Debug: (3) if (&User-Name =~ /(a)\./) { Mon May 13 17:06:00 2019 : Debug: (3) if (&User-Name =~ /(a)\./) -> FALSE Mon May 13 17:06:00 2019 : Debug: (3) } # if (&User-Name) = notfound Mon May 13 17:06:00 2019 : Debug: (3) } # policy filter_username = notfound Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: calling preprocess (rlm_preprocess) Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: returned from preprocess (rlm_preprocess) Mon May 13 17:06:00 2019 : Debug: (3) [preprocess] = ok Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: calling chap (rlm_chap) Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: returned from chap (rlm_chap) Mon May 13 17:06:00 2019 : Debug: (3) [chap] = noop Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: calling mschap (rlm_mschap) Mon May 13 17:06:00 2019 : Debug: (3) mschap: Found MS-CHAP attributes. Setting 'Auth-Type = mschap' Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: returned from mschap (rlm_mschap) Mon May 13 17:06:00 2019 : Debug: (3) [mschap] = ok Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: calling digest (rlm_digest) Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: returned from digest (rlm_digest) Mon May 13 17:06:00 2019 : Debug: (3) [digest] = noop Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: calling suffix (rlm_realm) Mon May 13 17:06:00 2019 : Debug: (3) suffix: Checking for suffix after "@" Mon May 13 17:06:00 2019 : Debug: (3) suffix: No '@' in User-Name = "antonio", looking up realm NULL Mon May 13 17:06:00 2019 : Debug: (3) suffix: No such realm "NULL" Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: returned from suffix (rlm_realm) Mon May 13 17:06:00 2019 : Debug: (3) [suffix] = noop Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: calling eap (rlm_eap) Mon May 13 17:06:00 2019 : Debug: (3) eap: No EAP-Message, not doing EAP Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: returned from eap (rlm_eap) Mon May 13 17:06:00 2019 : Debug: (3) [eap] = noop Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: calling files (rlm_files) Mon May 13 17:06:00 2019 : Debug: (3) files: Searching for user in group "CN=VLAN Accounting,OU=VLANs,OU=Groups,DC=ldap,DC=yieldmo,DC=com" Mon May 13 17:06:00 2019 : Info: rlm_ldap (ldap): Closing connection (11): Hit idle_timeout, was idle for 395 seconds Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): You probably need to lower "min" Mon May 13 17:06:00 2019 : Debug: rlm_ldap: Closing libldap handle 0x7f6ef4001150 Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): 0 of 0 connections in use. You may need to increase "spare" Mon May 13 17:06:00 2019 : Info: rlm_ldap (ldap): Opening additional connection (12), 1 of 32 pending slots used Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Connecting to ldap://10.0.151.172:389 Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): New libldap handle 0x7f6ee80010b0 Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Waiting for bind result... Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Bind successful Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Reserved connection (12) Mon May 13 17:06:00 2019 : Debug: (sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}}) Mon May 13 17:06:00 2019 : Debug: Parsed xlat tree: Mon May 13 17:06:00 2019 : Debug: literal --> (sAMAccountName= Mon May 13 17:06:00 2019 : Debug: XLAT-IF { Mon May 13 17:06:00 2019 : Debug: attribute --> Stripped-User-Name Mon May 13 17:06:00 2019 : Debug: } Mon May 13 17:06:00 2019 : Debug: XLAT-ELSE { Mon May 13 17:06:00 2019 : Debug: attribute --> User-Name Mon May 13 17:06:00 2019 : Debug: } Mon May 13 17:06:00 2019 : Debug: literal --> ) Mon May 13 17:06:00 2019 : Debug: (3) files: EXPAND (sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}}) Mon May 13 17:06:00 2019 : Debug: (3) files: --> (sAMAccountName=antonio) Mon May 13 17:06:00 2019 : Debug: (3) files: Performing search in "DC=ldap,DC=yieldmo,DC=com" with filter "(sAMAccountName=antonio)", scope "sub" Mon May 13 17:06:00 2019 : Debug: (3) files: Waiting for search result... Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Rebinding to URL ldap://ldap.yieldmo.com/CN=Configuration,DC=ldap,DC=yieldmo,DC=com Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Waiting for bind result... Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Bind successful Mon May 13 17:06:00 2019 : Debug: (3) files: User object found at DN "CN=antonio,CN=Users,DC=ldap,DC=yieldmo,DC=com" Mon May 13 17:06:00 2019 : Debug: (3) files: Checking for user in group objects Mon May 13 17:06:00 2019 : Debug: (&(objectClass=Group)(|(&(objectClass=group)(member=%{control:Ldap-UserDn}))(&(objectClass=top)(uniquemember=%{control:Ldap-UserDn})))) Mon May 13 17:06:00 2019 : Debug: Parsed xlat tree: Mon May 13 17:06:00 2019 : Debug: literal --> (&(objectClass=Group)(|(&(objectClass=group)(member= Mon May 13 17:06:00 2019 : Debug: attribute --> LDAP-UserDN Mon May 13 17:06:00 2019 : Debug: literal --> ))(&(objectClass=top)(uniquemember= Mon May 13 17:06:00 2019 : Debug: attribute --> LDAP-UserDN Mon May 13 17:06:00 2019 : Debug: literal --> )))) Mon May 13 17:06:00 2019 : Debug: (3) files: EXPAND (&(objectClass=Group)(|(&(objectClass=group)(member=%{control:Ldap-UserDn}))(&(objectClass=top)(uniquemember=%{control:Ldap-UserDn})))) Mon May 13 17:06:00 2019 : Debug: (3) files: --> (&(objectClass=Group)(|(&(objectClass=group)(member=CN\3dantonio\2cCN\3dUsers\2cDC\3dldap\2cDC\3dyieldmo\2cDC\3dcom))(&(objectClass=top)(uniquemember=CN\3dantonio\2cCN\3dUsers\2cDC\3dldap\2cDC\3dyieldmo\2cDC\3dcom)))) Mon May 13 17:06:00 2019 : Debug: (3) files: Waiting for bind result... Mon May 13 17:06:00 2019 : Debug: (3) files: Bind successful Mon May 13 17:06:00 2019 : Debug: (3) files: Performing search in "CN=VLAN Accounting,OU=VLANs,OU=Groups,DC=ldap,DC=yieldmo,DC=com" with filter "(&(objectClass=Group)(|(&(objectClass=group)(member=CN\3dantonio\2cCN\3dUsers\2cDC\3dldap\2cDC\3dyieldmo\2cDC\3dcom))(&(objectClass=top)(uniquemember=CN\3dantonio\2cCN\3dUsers\2cDC\3dldap\2cDC\3dyieldmo\2cDC\3dcom))))", scope "sub" Mon May 13 17:06:00 2019 : Debug: (3) files: Waiting for search result... Mon May 13 17:06:00 2019 : Debug: (3) files: Search returned no results Mon May 13 17:06:00 2019 : Debug: (3) files: Checking user object's memberOf attributes Mon May 13 17:06:00 2019 : Debug: (3) files: Performing unfiltered search in "CN=antonio,CN=Users,DC=ldap,DC=yieldmo,DC=com", scope "base" Mon May 13 17:06:00 2019 : Debug: (3) files: Waiting for search result... Mon May 13 17:06:00 2019 : Debug: (3) files: Processing memberOf value "CN=VLAN Engineering,OU=VLANs,OU=Groups,DC=ldap,DC=yieldmo,DC=com" as a DN Mon May 13 17:06:00 2019 : Debug: (3) files: Processing memberOf value "CN=XWikiAdmins,OU=xwiki,OU=Groups,DC=ldap,DC=yieldmo,DC=com" as a DN Mon May 13 17:06:00 2019 : Info: rlm_ldap (ldap): Deleting connection (12) - Was referred to a different LDAP server Mon May 13 17:06:00 2019 : Debug: rlm_ldap: Closing libldap handle 0x7f6ee80010b0 Mon May 13 17:06:00 2019 : Info: Need 3 more connections to reach min connections (3) Mon May 13 17:06:00 2019 : Info: rlm_ldap (ldap): Opening additional connection (13), 1 of 32 pending slots used Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Connecting to ldap://10.0.151.172:389 Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): New libldap handle 0x7f6ee80010b0 Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Waiting for bind result... Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Bind successful Mon May 13 17:06:00 2019 : Debug: (3) files: User is not a member of "CN=VLAN Accounting,OU=VLANs,OU=Groups,DC=ldap,DC=yieldmo,DC=com" Mon May 13 17:06:00 2019 : Debug: (3) files: Searching for user in group "CN=VLAN Engineering,OU=VLANs,OU=Groups,DC=ldap,DC=yieldmo,DC=com" Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Reserved connection (13) Mon May 13 17:06:00 2019 : Debug: (3) files: Using user DN from request "CN=antonio,CN=Users,DC=ldap,DC=yieldmo,DC=com" Mon May 13 17:06:00 2019 : Debug: (3) files: Checking for user in group objects Mon May 13 17:06:00 2019 : Debug: (&(objectClass=Group)(|(&(objectClass=group)(member=%{control:Ldap-UserDn}))(&(objectClass=top)(uniquemember=%{control:Ldap-UserDn})))) Mon May 13 17:06:00 2019 : Debug: Parsed xlat tree: Mon May 13 17:06:00 2019 : Debug: literal --> (&(objectClass=Group)(|(&(objectClass=group)(member= Mon May 13 17:06:00 2019 : Debug: attribute --> LDAP-UserDN Mon May 13 17:06:00 2019 : Debug: literal --> ))(&(objectClass=top)(uniquemember= Mon May 13 17:06:00 2019 : Debug: attribute --> LDAP-UserDN Mon May 13 17:06:00 2019 : Debug: literal --> )))) Mon May 13 17:06:00 2019 : Debug: (3) files: EXPAND (&(objectClass=Group)(|(&(objectClass=group)(member=%{control:Ldap-UserDn}))(&(objectClass=top)(uniquemember=%{control:Ldap-UserDn})))) Mon May 13 17:06:00 2019 : Debug: (3) files: --> (&(objectClass=Group)(|(&(objectClass=group)(member=CN\3dantonio\2cCN\3dUsers\2cDC\3dldap\2cDC\3dyieldmo\2cDC\3dcom))(&(objectClass=top)(uniquemember=CN\3dantonio\2cCN\3dUsers\2cDC\3dldap\2cDC\3dyieldmo\2cDC\3dcom)))) Mon May 13 17:06:00 2019 : Debug: (3) files: Performing search in "CN=VLAN Engineering,OU=VLANs,OU=Groups,DC=ldap,DC=yieldmo,DC=com" with filter "(&(objectClass=Group)(|(&(objectClass=group)(member=CN\3dantonio\2cCN\3dUsers\2cDC\3dldap\2cDC\3dyieldmo\2cDC\3dcom))(&(objectClass=top)(uniquemember=CN\3dantonio\2cCN\3dUsers\2cDC\3dldap\2cDC\3dyieldmo\2cDC\3dcom))))", scope "sub" Mon May 13 17:06:00 2019 : Debug: (3) files: Waiting for search result... Mon May 13 17:06:00 2019 : Debug: (3) files: User found in group object "CN=VLAN Engineering,OU=VLANs,OU=Groups,DC=ldap,DC=yieldmo,DC=com" Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Released connection (13) Mon May 13 17:06:00 2019 : Debug: (3) files: users: Matched entry DEFAULT at line 225 Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: returned from files (rlm_files) Mon May 13 17:06:00 2019 : Debug: (3) [files] = ok Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: calling ldap (rlm_ldap) Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Reserved connection (13) Mon May 13 17:06:00 2019 : Debug: (sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}}) Mon May 13 17:06:00 2019 : Debug: Parsed xlat tree: Mon May 13 17:06:00 2019 : Debug: literal --> (sAMAccountName= Mon May 13 17:06:00 2019 : Debug: XLAT-IF { Mon May 13 17:06:00 2019 : Debug: attribute --> Stripped-User-Name Mon May 13 17:06:00 2019 : Debug: } Mon May 13 17:06:00 2019 : Debug: XLAT-ELSE { Mon May 13 17:06:00 2019 : Debug: attribute --> User-Name Mon May 13 17:06:00 2019 : Debug: } Mon May 13 17:06:00 2019 : Debug: literal --> ) Mon May 13 17:06:00 2019 : Debug: (3) ldap: EXPAND (sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}}) Mon May 13 17:06:00 2019 : Debug: (3) ldap: --> (sAMAccountName=antonio) Mon May 13 17:06:00 2019 : Debug: (3) ldap: Performing search in "DC=ldap,DC=yieldmo,DC=com" with filter "(sAMAccountName=antonio)", scope "sub" Mon May 13 17:06:00 2019 : Debug: (3) ldap: Waiting for search result... Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Rebinding to URL ldap://ldap.yieldmo.com/CN=Configuration,DC=ldap,DC=yieldmo,DC=com Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Waiting for bind result... Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Bind successful Mon May 13 17:06:00 2019 : Debug: (3) ldap: User object found at DN "CN=antonio,CN=Users,DC=ldap,DC=yieldmo,DC=com" Mon May 13 17:06:00 2019 : Debug: (3) ldap: Processing user attributes Mon May 13 17:06:00 2019 : Debug: (3) ldap: control:Password-With-Header += '{SSHA}6OROoSPG9FfFPEm6nEGhpm37x4hOSGJi' Mon May 13 17:06:00 2019 : Info: rlm_ldap (ldap): Deleting connection (13) - Was referred to a different LDAP server Mon May 13 17:06:00 2019 : Debug: rlm_ldap: Closing libldap handle 0x7f6ee80010b0 Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: returned from ldap (rlm_ldap) Mon May 13 17:06:00 2019 : Debug: (3) [ldap] = updated Mon May 13 17:06:00 2019 : Debug: (3) if ((ok || updated) && User-Password) { Mon May 13 17:06:00 2019 : Debug: (3) if ((ok || updated) && User-Password) -> FALSE Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: calling expiration (rlm_expiration) Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: returned from expiration (rlm_expiration) Mon May 13 17:06:00 2019 : Debug: (3) [expiration] = noop Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: calling logintime (rlm_logintime) Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: returned from logintime (rlm_logintime) Mon May 13 17:06:00 2019 : Debug: (3) [logintime] = noop Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: calling pap (rlm_pap) Mon May 13 17:06:00 2019 : Debug: (3) pap: Converted: &control:Password-With-Header = '{SSHA}6OROoSPG9FfFPEm6nEGhpm37x4hOSGJi' -> &control:SSHA1-Password = '0x364f524f6f5350473946664650456d366e454768706d33377834684f53474a69' Mon May 13 17:06:00 2019 : Debug: (3) pap: Removing &control:Password-With-Header Mon May 13 17:06:00 2019 : Debug: (3) pap: Normalizing SSHA1-Password from base64 encoding, 32 bytes -> 24 bytes Mon May 13 17:06:00 2019 : WARNING: (3) pap: Auth-Type already set. Not setting to PAP Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: returned from pap (rlm_pap) Mon May 13 17:06:00 2019 : Debug: (3) [pap] = noop Mon May 13 17:06:00 2019 : Debug: (3) } # authorize = updated Mon May 13 17:06:00 2019 : Debug: (3) Found Auth-Type = mschap Mon May 13 17:06:00 2019 : Debug: (3) # Executing group from file /etc/freeradius/sites-enabled/default Mon May 13 17:06:00 2019 : Debug: (3) authenticate { Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authenticate]: calling mschap (rlm_mschap) Mon May 13 17:06:00 2019 : Debug: (3) mschap: Client is using MS-CHAPv1 with NT-Password Mon May 13 17:06:00 2019 : Debug: (3) mschap: Executing: /usr/bin/ntlm_auth --request-nt-key --username=%{%{Stripped-User-Name}:-%{%{User-Name}:-None}} --challenge=%{%{mschap:Challenge}:-00} --nt-response=%{%{mschap:NT-Response}:-00}: Mon May 13 17:06:00 2019 : Debug: --username=%{%{Stripped-User-Name}:-%{%{User-Name}:-None}} Mon May 13 17:06:00 2019 : Debug: Parsed xlat tree: Mon May 13 17:06:00 2019 : Debug: literal --> --username= Mon May 13 17:06:00 2019 : Debug: XLAT-IF { Mon May 13 17:06:00 2019 : Debug: attribute --> Stripped-User-Name Mon May 13 17:06:00 2019 : Debug: } Mon May 13 17:06:00 2019 : Debug: XLAT-ELSE { Mon May 13 17:06:00 2019 : Debug: XLAT-IF { Mon May 13 17:06:00 2019 : Debug: attribute --> User-Name Mon May 13 17:06:00 2019 : Debug: } Mon May 13 17:06:00 2019 : Debug: XLAT-ELSE { Mon May 13 17:06:00 2019 : Debug: literal --> None Mon May 13 17:06:00 2019 : Debug: } Mon May 13 17:06:00 2019 : Debug: } Mon May 13 17:06:00 2019 : Debug: (3) mschap: EXPAND --username=%{%{Stripped-User-Name}:-%{%{User-Name}:-None}} Mon May 13 17:06:00 2019 : Debug: (3) mschap: --> --username=antonio Mon May 13 17:06:00 2019 : Debug: --challenge=%{%{mschap:Challenge}:-00} Mon May 13 17:06:00 2019 : Debug: Parsed xlat tree: Mon May 13 17:06:00 2019 : Debug: literal --> --challenge= Mon May 13 17:06:00 2019 : Debug: XLAT-IF { Mon May 13 17:06:00 2019 : Debug: xlat --> mschap Mon May 13 17:06:00 2019 : Debug: { Mon May 13 17:06:00 2019 : Debug: literal --> Challenge Mon May 13 17:06:00 2019 : Debug: } Mon May 13 17:06:00 2019 : Debug: } Mon May 13 17:06:00 2019 : Debug: XLAT-ELSE { Mon May 13 17:06:00 2019 : Debug: literal --> 00 Mon May 13 17:06:00 2019 : Debug: } Mon May 13 17:06:00 2019 : Debug: (3) mschap: mschap1: 2e Mon May 13 17:06:00 2019 : Debug: (3) mschap: EXPAND --challenge=%{%{mschap:Challenge}:-00} Mon May 13 17:06:00 2019 : Debug: (3) mschap: --> --challenge=2e3ecfc58cff680f Mon May 13 17:06:00 2019 : Debug: --nt-response=%{%{mschap:NT-Response}:-00} Mon May 13 17:06:00 2019 : Debug: Parsed xlat tree: Mon May 13 17:06:00 2019 : Debug: literal --> --nt-response= Mon May 13 17:06:00 2019 : Debug: XLAT-IF { Mon May 13 17:06:00 2019 : Debug: xlat --> mschap Mon May 13 17:06:00 2019 : Debug: { Mon May 13 17:06:00 2019 : Debug: literal --> NT-Response Mon May 13 17:06:00 2019 : Debug: } Mon May 13 17:06:00 2019 : Debug: } Mon May 13 17:06:00 2019 : Debug: XLAT-ELSE { Mon May 13 17:06:00 2019 : Debug: literal --> 00 Mon May 13 17:06:00 2019 : Debug: } Mon May 13 17:06:00 2019 : Debug: (3) mschap: EXPAND --nt-response=%{%{mschap:NT-Response}:-00} Mon May 13 17:06:00 2019 : Debug: (3) mschap: --> --nt-response=c067bb42d3a35102436e299186f135f6f664ea811f2a148f Mon May 13 17:06:00 2019 : ERROR: (3) mschap: Program returned code (1) and output 'Reading winbind reply failed! (0xc0000001)' Mon May 13 17:06:00 2019 : ERROR: (3) mschap: Reading winbind reply failed! (0xc0000001) Mon May 13 17:06:00 2019 : Debug: (3) mschap: Authentication failed Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authenticate]: returned from mschap (rlm_mschap) Mon May 13 17:06:00 2019 : Debug: (3) [mschap] = fail Mon May 13 17:06:00 2019 : Debug: (3) } # authenticate = fail Mon May 13 17:06:00 2019 : Debug: (3) Failed to authenticate the user Mon May 13 17:06:00 2019 : Debug: (3) Using Post-Auth-Type Reject Mon May 13 17:06:00 2019 : Debug: (3) # Executing group from file /etc/freeradius/sites-enabled/default Mon May 13 17:06:00 2019 : Debug: (3) Post-Auth-Type REJECT { Mon May 13 17:06:00 2019 : Debug: (3) modsingle[post-auth]: calling eap (rlm_eap) Mon May 13 17:06:00 2019 : Debug: (3) eap: Request didn't contain an EAP-Message, not inserting EAP-Failure Mon May 13 17:06:00 2019 : Debug: (3) modsingle[post-auth]: returned from eap (rlm_eap) Mon May 13 17:06:00 2019 : Debug: (3) [eap] = noop Mon May 13 17:06:00 2019 : Debug: (3) policy remove_reply_message_if_eap { Mon May 13 17:06:00 2019 : Debug: (3) if (&reply:EAP-Message && &reply:Reply-Message) { Mon May 13 17:06:00 2019 : Debug: (3) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE Mon May 13 17:06:00 2019 : Debug: (3) else { Mon May 13 17:06:00 2019 : Debug: (3) modsingle[post-auth]: calling noop (rlm_always) Mon May 13 17:06:00 2019 : Debug: (3) modsingle[post-auth]: returned from noop (rlm_always) Mon May 13 17:06:00 2019 : Debug: (3) [noop] = noop Mon May 13 17:06:00 2019 : Debug: (3) } # else = noop Mon May 13 17:06:00 2019 : Debug: (3) } # policy remove_reply_message_if_eap = noop Mon May 13 17:06:00 2019 : Debug: (3) } # Post-Auth-Type REJECT = noop Mon May 13 17:06:00 2019 : Auth: (3) Login incorrect (mschap: Program returned code (1) and output 'Reading winbind reply failed! (0xc0000001)'): [antonio/<via Auth-Type = mschap>] (from client vpn port 0) Mon May 13 17:06:00 2019 : Debug: (3) Delaying response for 1.000000 seconds Mon May 13 17:06:00 2019 : Debug: Thread 2 waiting to be assigned a request Mon May 13 17:06:01 2019 : Debug: Waking up in 0.8 seconds. Mon May 13 17:06:01 2019 : Debug: (3) Sending delayed response Mon May 13 17:06:01 2019 : Debug: (3) Sent Access-Reject Id 7 from 10.0.153.139:1812 to 10.0.0.191:61367 length 77 Mon May 13 17:06:01 2019 : Debug: (3) Tunnel-Type = VLAN Mon May 13 17:06:01 2019 : Debug: (3) Tunnel-Medium-Type = IEEE-802 Mon May 13 17:06:01 2019 : Debug: (3) Tunnel-Private-Group-Id = "10" Mon May 13 17:06:01 2019 : Debug: (3) MS-CHAP-Error = "\000E=691 R=1 C=ed4c6cae95574d22 V=2" Mon May 13 17:06:01 2019 : Debug: Waking up in 3.9 seconds. Mon May 13 17:06:05 2019 : Debug: (3) Cleaning up request packet ID 7 with timestamp +1631 Mon May 13 17:06:05 2019 : Info: Ready to process requests And just in case, this is radtest using mschap against Freeradius running on EC2: $ radtest -t mschap antonio '<MY_PASSWORD>' 10.0.1.187 0 <MY_SECRET> Sent Access-Request Id 27 from 0.0.0.0:55903 to 10.0.1.187:1812 length 133 User-Name = "antonio" MS-CHAP-Password = "<MY_PASSWORD>" NAS-IP-Address = 127.0.0.1 NAS-Port = 0 Message-Authenticator = 0x00 Cleartext-Password = "<MY_PASSWORD>" MS-CHAP-Challenge = 0x9508ba134034af62 MS-CHAP-Response = 0x0001000000000000000000000000000000000000000000000000884e7789a08f90f4f58ecef575a97965556a3f9bc8fefe5a Received Access-Accept Id 27 from 10.0.1.187:1812 to 172.16.0.54:55903 length 36 Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = "10"

2 1

update disconnect is not working in accounting section
by One Zero Art 11 May '19

11 May '19

Hi, I am trying to disconnect the user in the accounting section. Is FreeRadius support auto disconnection? In the accounting section, I tried this update disconnect { Framed-IP-Address = "%{Framed-IP-Address}" User-Name = "%{request:User-Name}" } This giving me error in accounting section when debuging. I am also using CoA successfully. CoA is working great. This error message showing in debug (7) if (&control:Tmp-Integer-4 == 1){ (7) if (&control:Tmp-Integer-4 == 1) -> TRUE (7) if (&control:Tmp-Integer-4 == 1) { (7) if (&control:Tmp-Integer-2 > &control:Tmp-Integer-3){ (7) if (&control:Tmp-Integer-2 > &control:Tmp-Integer-3) -> TRUE (7) if (&control:Tmp-Integer-2 > &control:Tmp-Integer-3) { (7) update disconnect { (7) *WARNING: List "disconnect" is not available (7) ERROR: Mapping "%{Framed-IP-Address}" -> "Framed-IP-Address" invalid in this context* (7) } # update disconnect = invalid (7) } # if (&control:Tmp-Integer-2 > &control:Tmp-Integer-3) = invalid (7) } # if (&control:Tmp-Integer-4 == 1) = invalid (7) } # accounting = invalid (7) Sent CoA-Request Id 89 from 0.0.0.0:53274 to 192.168.0.10:3799 length 47 (7) Framed-IP-Address = 0.0.0.0 (7) User-Name = "user" (7) Mikrotik-Rate-Limit = "10M/10M" (7) Not sending reply to client. (7) Finished request (7) Cleaning up request packet ID 52 with timestamp +266 Waking up in 2.4 seconds. (7) Clearing existing &reply: attributes (7) Received CoA-NAK Id 89 from 192.168.0.10:3799 to 192.168.0.2:53274 length 42 (7) Error-Cause = Unsupported-Extension (7) NAS-Identifier = "MikroTik" (7) NAS-IP-Address = 192.168.0.10 (7) # Executing section post-proxy from file /etc/freeradius/3.0/sites-enabled/default (7) post-proxy { (7) eap: No pre-existing handler found (7) [eap] = noop (7) } # post-proxy = noop (7) Cleaning up request packet ID 52 with timestamp +266 Ready to process requests Thank you

2 1

Dynamic Client and TCP/TLS
by Karim Benayed 11 May '19

11 May '19

Hi, I am trying to setup Dynamic Client configuration where Redis is used to retrieve the secret, setup the FreeRADIUS-Client attributes and redirect for authentication. The model is working perfectly for UDP with Dynamic Clients and for TCP/TLS non-dynamic clients. The moment I enable Dynamic Clients against the TCP/TLS configuration, I get the following error: Error: Receive - Error receiving packet. Transport endpoint is not connected. This error is followed by Error, Ignoring request ... from unknown client. I tried to re-install and out of the box configuration, Used Fedora built and a 3.0.19 based compiled built against the default configuration and keys. The response is unfortunately exactly the same. Lastly, I tried to connect via openssl s_client host_ip and via FreeRadius acting as a proxy. It is always the same error :( To reproduce, Please try the default configuration, add tls to sites-enabled and connect via a radsec client. I truly appreciate any hints on if anything special is required. Thanks you, Karim

2 1

Update Noop In Authorize Section
by One Zero Art 10 May '19

10 May '19

Hi, I am trying to reject user by checking session time from radacct. I am using 4 SQL query and checking various things in debug mode every SQL query looking good but the only issue updates control noop. Debug mode shows update control noop. Below is my SQL queries. /default authorize section ============================================================= update control { Tmp-String-1 := "%{sql:=============================='}" Tmp-String-2 := "%{sql:================================}" Tmp-String-3 := "%{sql:=================================}'}" Tmp-String-3 := "%{expr:%{control:Tmp-String-3} * 3600}" Tmp-String-4 := "%{sql:S=================================='}" } if(%{control:Tmp-String-4} >= 1){ if(%{control:Tmp-String-2} >= %{control:Tmp-String-3}){ update reply { Reply-Message := 'Reached Session Limit' } reject } } All SQL query working fine and showing exact value. The only problem is that update control showing noop. Some reason update control is not working. Thank you very much

2 4