Re: MSCHAPv2 Module with Stripped-Username - no ActiveDirectory
Markus Maurer
lists at v-net.tk
Mon Nov 12 11:09:31 CET 2018
You *cannot* make this work using MSCHAP and AD.It is working.
Look at this:
Mon Nov 12 11:04:40 2018 : Debug: (0) Received Access-Request Id 8 from 192.168.2.100:58006 to 192.168.1.100:1812 length 170
Mon Nov 12 11:04:40 2018 : Debug: (0) User-Name = "johndoe:123456"
Mon Nov 12 11:04:40 2018 : Debug: (0) NAS-Port-Type = Virtual
Mon Nov 12 11:04:40 2018 : Debug: (0) Service-Type = Framed-User
Mon Nov 12 11:04:40 2018 : Debug: (0) NAS-Port = 5
Mon Nov 12 11:04:40 2018 : Debug: (0) NAS-Port-Id = "con2"
Mon Nov 12 11:04:40 2018 : Debug: (0) NAS-IP-Address = 188.188.188.188
Mon Nov 12 11:04:40 2018 : Debug: (0) Called-Station-Id = "188.188.188.188[4500]"
Mon Nov 12 11:04:40 2018 : Debug: (0) Calling-Station-Id = "66.66.66.66[4500]"
Mon Nov 12 11:04:40 2018 : Debug: (0) EAP-Message = 0x02000019016d61726b75732e6d61757265723a313131313131
Mon Nov 12 11:04:40 2018 : Debug: (0) NAS-Identifier = "strongSwan"
Mon Nov 12 11:04:40 2018 : Debug: (0) Message-Authenticator = 0xc990005408b55db605a48c5ba965d7da
Mon Nov 12 11:04:40 2018 : Debug: (0) session-state: No State attribute
Mon Nov 12 11:04:40 2018 : Debug: (0) # Executing section authorize from file /etc/raddb/sites-enabled/default
Mon Nov 12 11:04:40 2018 : Debug: (0) authorize {
Mon Nov 12 11:04:40 2018 : Debug: (0) if ( &User-Name =~ /^(.*):([0-9]{6})$/) {
Mon Nov 12 11:04:40 2018 : Debug: No matches
Mon Nov 12 11:04:40 2018 : Debug: Adding 3 matches
Mon Nov 12 11:04:40 2018 : Debug: (0) if ( &User-Name =~ /^(.*):([0-9]{6})$/) -> TRUE
Mon Nov 12 11:04:40 2018 : Debug: (0) if ( &User-Name =~ /^(.*):([0-9]{6})$/) {
Mon Nov 12 11:04:40 2018 : Debug: (0) update request {
Mon Nov 12 11:04:40 2018 : Debug: (0) 1/3 Found: johndoe (14)
Mon Nov 12 11:04:40 2018 : Debug: (0) EXPAND %{1}
Mon Nov 12 11:04:40 2018 : Debug: (0) --> johndoe
Mon Nov 12 11:04:40 2018 : Debug: (0) Stripped-User-Name := johndoe
Mon Nov 12 11:04:40 2018 : Debug: (0) 2/3 Found: 123456 (7)
Mon Nov 12 11:04:40 2018 : Debug: (0) EXPAND %{2}
Mon Nov 12 11:04:40 2018 : Debug: (0) --> 123456
Mon Nov 12 11:04:40 2018 : Debug: (0) User-OTP := 123456
Mon Nov 12 11:04:40 2018 : Debug: (0) } # update request = noop
Mon Nov 12 11:04:40 2018 : Debug: (0) } # if ( &User-Name =~ /^(.*):([0-9]{6})$/) = noop
Mon Nov 12 11:04:40 2018 : Debug: (0) modsingle[authorize]: calling preprocess (rlm_preprocess)
Mon Nov 12 11:04:40 2018 : Debug: (0) modsingle[authorize]: returned from preprocess (rlm_preprocess)
Mon Nov 12 11:04:40 2018 : Debug: (0) [preprocess] = ok
Mon Nov 12 11:04:40 2018 : Debug: (0) modsingle[authorize]: calling files (rlm_files)
Mon Nov 12 11:04:40 2018 : Debug: %{%{Stripped-User-Name}:-%{User-Name}}
Mon Nov 12 11:04:40 2018 : Debug: Parsed xlat tree:
Mon Nov 12 11:04:40 2018 : Debug: XLAT-IF {
Mon Nov 12 11:04:40 2018 : Debug: attribute --> Stripped-User-Name
Mon Nov 12 11:04:40 2018 : Debug: }
Mon Nov 12 11:04:40 2018 : Debug: XLAT-ELSE {
Mon Nov 12 11:04:40 2018 : Debug: attribute --> User-Name
Mon Nov 12 11:04:40 2018 : Debug: }
Mon Nov 12 11:04:40 2018 : Debug: (0) files: EXPAND %{%{Stripped-User-Name}:-%{User-Name}}
Mon Nov 12 11:04:40 2018 : Debug: (0) files: --> johndoe
Mon Nov 12 11:04:40 2018 : Debug: (0) files: users: Matched entry johndoe at line 4
Mon Nov 12 11:04:40 2018 : Debug: (0) files: ::: FROM 0 TO 0 MAX 0
Mon Nov 12 11:04:40 2018 : Debug: (0) files: ::: TO in 0 out 0
Mon Nov 12 11:04:40 2018 : Debug: (0) modsingle[authorize]: returned from files (rlm_files)
Mon Nov 12 11:04:40 2018 : Debug: (0) [files] = ok
Mon Nov 12 11:04:40 2018 : Debug: (0) modsingle[authorize]: calling expiration (rlm_expiration)
Mon Nov 12 11:04:40 2018 : Debug: (0) modsingle[authorize]: returned from expiration (rlm_expiration)
Mon Nov 12 11:04:40 2018 : Debug: (0) [expiration] = noop
Mon Nov 12 11:04:40 2018 : Debug: (0) modsingle[authorize]: calling logintime (rlm_logintime)
Mon Nov 12 11:04:40 2018 : Debug: (0) modsingle[authorize]: returned from logintime (rlm_logintime)
Mon Nov 12 11:04:40 2018 : Debug: (0) [logintime] = noop
Mon Nov 12 11:04:40 2018 : Debug: (0) modsingle[authorize]: calling pap (rlm_pap)
Mon Nov 12 11:04:40 2018 : Debug: (0) modsingle[authorize]: returned from pap (rlm_pap)
Mon Nov 12 11:04:40 2018 : Debug: (0) [pap] = updated
Mon Nov 12 11:04:40 2018 : Debug: (0) } # authorize = updated
Mon Nov 12 11:04:40 2018 : Debug: (0) Found Auth-Type = PAP
Mon Nov 12 11:04:40 2018 : Debug: (0) # Executing group from file /etc/raddb/sites-enabled/default
Mon Nov 12 11:04:40 2018 : Debug: (0) Auth-Type PAP {
Mon Nov 12 11:04:40 2018 : Debug: (0) modsingle[authenticate]: calling pap (rlm_pap)
Mon Nov 12 11:04:40 2018 : Debug: (0) pap: Login attempt with password "123456" (6)
Mon Nov 12 11:04:40 2018 : Debug: (0) pap: Comparing with "known good" Cleartext-Password "123456" (6)
Mon Nov 12 11:04:40 2018 : Debug: (0) pap: User authenticated successfully
Mon Nov 12 11:04:40 2018 : Debug: (0) modsingle[authenticate]: returned from pap (rlm_pap)
Mon Nov 12 11:04:40 2018 : Debug: (0) [pap] = ok
Mon Nov 12 11:04:40 2018 : Debug: (0) if (ok) {
Mon Nov 12 11:04:40 2018 : Debug: (0) if (ok) -> TRUE
Mon Nov 12 11:04:40 2018 : Debug: (0) if (ok) {
Mon Nov 12 11:04:40 2018 : Debug: (0) modsingle[authenticate]: calling eap (rlm_eap)
Mon Nov 12 11:04:40 2018 : Debug: (0) eap: Peer sent packet with method EAP Identity (1)
Mon Nov 12 11:04:40 2018 : Debug: (0) eap: Calling submodule eap_mschapv2 to process data
Mon Nov 12 11:04:40 2018 : Debug: (0) eap_mschapv2: Issuing Challenge
Mon Nov 12 11:04:40 2018 : Debug: (0) eap: Sending EAP Request (code 1) ID 1 length 43
Mon Nov 12 11:04:40 2018 : Debug: (0) eap: EAP session adding &reply:State = 0xfb6bfe4bfb6ae43b
Mon Nov 12 11:04:40 2018 : Debug: (0) modsingle[authenticate]: returned from eap (rlm_eap)
Mon Nov 12 11:04:40 2018 : Debug: (0) [eap] = handled
Mon Nov 12 11:04:40 2018 : Debug: (0) } # if (ok) = handled
Mon Nov 12 11:04:40 2018 : Debug: (0) } # Auth-Type PAP = handled
Mon Nov 12 11:04:40 2018 : Debug: (0) Using Post-Auth-Type Challenge
Mon Nov 12 11:04:40 2018 : Debug: (0) # Executing group from file /etc/raddb/sites-enabled/default
Mon Nov 12 11:04:40 2018 : Debug: (0) Challenge { ... } # empty sub-section is ignored
Mon Nov 12 11:04:40 2018 : Debug: (0) session-state: Nothing to cache
Mon Nov 12 11:04:40 2018 : Debug: (0) Sent Access-Challenge Id 8 from 192.168.1.100:1812 to 192.168.2.100:58006 length 0
Mon Nov 12 11:04:40 2018 : Debug: (0) EAP-Message = 0x0101002b1a010100261030e3952e2c9124e7da1b5349c01cd33d667265657261646975732d332e302e3133
Mon Nov 12 11:04:40 2018 : Debug: (0) Message-Authenticator = 0x00000000000000000000000000000000
Mon Nov 12 11:04:40 2018 : Debug: (0) State = 0xfb6bfe4bfb6ae43b45f5a1d5430de6d2
Mon Nov 12 11:04:40 2018 : Debug: (0) Finished request
Mon Nov 12 11:04:40 2018 : Debug: Waking up in 4.9 seconds.
Mon Nov 12 11:04:40 2018 : Debug: (1) Received Access-Request Id 9 from 192.168.2.100:58006 to 192.168.1.100:1812 length 242
Mon Nov 12 11:04:40 2018 : Debug: (1) User-Name = "johndoe:123456"
Mon Nov 12 11:04:40 2018 : Debug: (1) NAS-Port-Type = Virtual
Mon Nov 12 11:04:40 2018 : Debug: (1) Service-Type = Framed-User
Mon Nov 12 11:04:40 2018 : Debug: (1) NAS-Port = 5
Mon Nov 12 11:04:40 2018 : Debug: (1) NAS-Port-Id = "con2"
Mon Nov 12 11:04:40 2018 : Debug: (1) NAS-IP-Address = 188.188.188.188
Mon Nov 12 11:04:40 2018 : Debug: (1) Called-Station-Id = "188.188.188.188[4500]"
Mon Nov 12 11:04:40 2018 : Debug: (1) Calling-Station-Id = "66.66.66.66[4500]"
Mon Nov 12 11:04:40 2018 : Debug: (1) EAP-Message = 0x0201004f1a0201004a3145c827eec3e80f01d82457f43e2e188100000000000000004caa9abd0548379b7e274a01c7faf807a7be4b3f16980725006d61726b75732e6d61757265723a313131313131
Mon Nov 12 11:04:40 2018 : Debug: (1) NAS-Identifier = "strongSwan"
Mon Nov 12 11:04:40 2018 : Debug: (1) State = 0xfb6bfe4bfb6ae43b45f5a1d5430de6d2
Mon Nov 12 11:04:40 2018 : Debug: (1) Message-Authenticator = 0x502608d30fe0da78dfab8667b1a66496
Mon Nov 12 11:04:40 2018 : Debug: (1) session-state: No cached attributes
Mon Nov 12 11:04:40 2018 : Debug: (1) # Executing section authorize from file /etc/raddb/sites-enabled/default
Mon Nov 12 11:04:40 2018 : Debug: (1) authorize {
Mon Nov 12 11:04:40 2018 : Debug: (1) if ( &User-Name =~ /^(.*):([0-9]{6})$/) {
Mon Nov 12 11:04:40 2018 : Debug: No matches
Mon Nov 12 11:04:40 2018 : Debug: Adding 3 matches
Mon Nov 12 11:04:40 2018 : Debug: (1) if ( &User-Name =~ /^(.*):([0-9]{6})$/) -> TRUE
Mon Nov 12 11:04:40 2018 : Debug: (1) if ( &User-Name =~ /^(.*):([0-9]{6})$/) {
Mon Nov 12 11:04:40 2018 : Debug: (1) update request {
Mon Nov 12 11:04:40 2018 : Debug: (1) 1/3 Found: johndoe (14)
Mon Nov 12 11:04:40 2018 : Debug: (1) EXPAND %{1}
Mon Nov 12 11:04:40 2018 : Debug: (1) --> johndoe
Mon Nov 12 11:04:40 2018 : Debug: (1) Stripped-User-Name := johndoe
Mon Nov 12 11:04:40 2018 : Debug: (1) 2/3 Found: 123456 (7)
Mon Nov 12 11:04:40 2018 : Debug: (1) EXPAND %{2}
Mon Nov 12 11:04:40 2018 : Debug: (1) --> 123456
Mon Nov 12 11:04:40 2018 : Debug: (1) User-OTP := 123456
Mon Nov 12 11:04:40 2018 : Debug: (1) } # update request = noop
Mon Nov 12 11:04:40 2018 : Debug: (1) } # if ( &User-Name =~ /^(.*):([0-9]{6})$/) = noop
Mon Nov 12 11:04:40 2018 : Debug: (1) modsingle[authorize]: calling preprocess (rlm_preprocess)
Mon Nov 12 11:04:40 2018 : Debug: (1) modsingle[authorize]: returned from preprocess (rlm_preprocess)
Mon Nov 12 11:04:40 2018 : Debug: (1) [preprocess] = ok
Mon Nov 12 11:04:40 2018 : Debug: (1) modsingle[authorize]: calling files (rlm_files)
Mon Nov 12 11:04:40 2018 : Debug: %{%{Stripped-User-Name}:-%{User-Name}}
Mon Nov 12 11:04:40 2018 : Debug: Parsed xlat tree:
Mon Nov 12 11:04:40 2018 : Debug: XLAT-IF {
Mon Nov 12 11:04:40 2018 : Debug: attribute --> Stripped-User-Name
Mon Nov 12 11:04:40 2018 : Debug: }
Mon Nov 12 11:04:40 2018 : Debug: XLAT-ELSE {
Mon Nov 12 11:04:40 2018 : Debug: attribute --> User-Name
Mon Nov 12 11:04:40 2018 : Debug: }
Mon Nov 12 11:04:40 2018 : Debug: (1) files: EXPAND %{%{Stripped-User-Name}:-%{User-Name}}
Mon Nov 12 11:04:40 2018 : Debug: (1) files: --> johndoe
Mon Nov 12 11:04:40 2018 : Debug: (1) files: users: Matched entry johndoe at line 4
Mon Nov 12 11:04:40 2018 : Debug: (1) files: ::: FROM 0 TO 0 MAX 0
Mon Nov 12 11:04:40 2018 : Debug: (1) files: ::: TO in 0 out 0
Mon Nov 12 11:04:40 2018 : Debug: (1) modsingle[authorize]: returned from files (rlm_files)
Mon Nov 12 11:04:40 2018 : Debug: (1) [files] = ok
Mon Nov 12 11:04:40 2018 : Debug: (1) modsingle[authorize]: calling expiration (rlm_expiration)
Mon Nov 12 11:04:40 2018 : Debug: (1) modsingle[authorize]: returned from expiration (rlm_expiration)
Mon Nov 12 11:04:40 2018 : Debug: (1) [expiration] = noop
Mon Nov 12 11:04:40 2018 : Debug: (1) modsingle[authorize]: calling logintime (rlm_logintime)
Mon Nov 12 11:04:40 2018 : Debug: (1) modsingle[authorize]: returned from logintime (rlm_logintime)
Mon Nov 12 11:04:40 2018 : Debug: (1) [logintime] = noop
Mon Nov 12 11:04:40 2018 : Debug: (1) modsingle[authorize]: calling pap (rlm_pap)
Mon Nov 12 11:04:40 2018 : Debug: (1) modsingle[authorize]: returned from pap (rlm_pap)
Mon Nov 12 11:04:40 2018 : Debug: (1) [pap] = updated
Mon Nov 12 11:04:40 2018 : Debug: (1) } # authorize = updated
Mon Nov 12 11:04:40 2018 : Debug: (1) Found Auth-Type = PAP
Mon Nov 12 11:04:40 2018 : Debug: (1) # Executing group from file /etc/raddb/sites-enabled/default
Mon Nov 12 11:04:40 2018 : Debug: (1) Auth-Type PAP {
Mon Nov 12 11:04:40 2018 : Debug: (1) modsingle[authenticate]: calling pap (rlm_pap)
Mon Nov 12 11:04:40 2018 : Debug: (1) pap: Login attempt with password "123456" (6)
Mon Nov 12 11:04:40 2018 : Debug: (1) pap: Comparing with "known good" Cleartext-Password "123456" (6)
Mon Nov 12 11:04:40 2018 : Debug: (1) pap: User authenticated successfully
Mon Nov 12 11:04:40 2018 : Debug: (1) modsingle[authenticate]: returned from pap (rlm_pap)
Mon Nov 12 11:04:40 2018 : Debug: (1) [pap] = ok
Mon Nov 12 11:04:40 2018 : Debug: (1) if (ok) {
Mon Nov 12 11:04:40 2018 : Debug: (1) if (ok) -> TRUE
Mon Nov 12 11:04:40 2018 : Debug: (1) if (ok) {
Mon Nov 12 11:04:40 2018 : Debug: (1) modsingle[authenticate]: calling eap (rlm_eap)
Mon Nov 12 11:04:40 2018 : Debug: (1) eap: Expiring EAP session with state 0xfb6bfe4bfb6ae43b
Mon Nov 12 11:04:40 2018 : Debug: (1) eap: Finished EAP session with state 0xfb6bfe4bfb6ae43b
Mon Nov 12 11:04:40 2018 : Debug: (1) eap: Previous EAP request found for state 0xfb6bfe4bfb6ae43b, released from the list
Mon Nov 12 11:04:40 2018 : Debug: (1) eap: Peer sent packet with method EAP MSCHAPv2 (26)
Mon Nov 12 11:04:40 2018 : Debug: (1) eap: Calling submodule eap_mschapv2 to process data
Mon Nov 12 11:04:40 2018 : Debug: (1) eap_mschapv2: # Executing group from file /etc/raddb/sites-enabled/default
Mon Nov 12 11:04:40 2018 : Debug: (1) eap_mschapv2: authenticate {
Mon Nov 12 11:04:40 2018 : Debug: (1) eap_mschapv2: modsingle[authenticate]: calling mschap (rlm_mschap)
Mon Nov 12 11:04:40 2018 : Debug: (1) mschap: Found Cleartext-Password, hashing to create NT-Password
Mon Nov 12 11:04:40 2018 : Debug: (1) mschap: Found Cleartext-Password, hashing to create LM-Password
Mon Nov 12 11:04:40 2018 : Debug: (1) mschap: Creating challenge hash with username: johndoe:123456
Mon Nov 12 11:04:40 2018 : Debug: (1) mschap: Client is using MS-CHAPv2
Mon Nov 12 11:04:40 2018 : Debug: (1) mschap: Executing: /usr/bin/ntlm_auth --request-nt-key --username=%{Stripped-User-Name} --domain=%{%{mschap:NT-Domain}:-EXAMPLEDOM} --challenge=%{mschap:Challenge:-00} --nt-response=%{mschap:NT-Response:-00}:
Mon Nov 12 11:04:40 2018 : Debug: --username=%{Stripped-User-Name}
Mon Nov 12 11:04:40 2018 : Debug: Parsed xlat tree:
Mon Nov 12 11:04:40 2018 : Debug: literal --> --username=
Mon Nov 12 11:04:40 2018 : Debug: attribute --> Stripped-User-Name
Mon Nov 12 11:04:40 2018 : Debug: (1) mschap: EXPAND --username=%{Stripped-User-Name}
Mon Nov 12 11:04:40 2018 : Debug: (1) mschap: --> --username=johndoe
Mon Nov 12 11:04:40 2018 : Debug: --domain=%{%{mschap:NT-Domain}:-EXAMPLEDOM}
Mon Nov 12 11:04:40 2018 : Debug: Parsed xlat tree:
Mon Nov 12 11:04:40 2018 : Debug: literal --> --domain=
Mon Nov 12 11:04:40 2018 : Debug: XLAT-IF {
Mon Nov 12 11:04:40 2018 : Debug: xlat --> mschap
Mon Nov 12 11:04:40 2018 : Debug: {
Mon Nov 12 11:04:40 2018 : Debug: literal --> NT-Domain
Mon Nov 12 11:04:40 2018 : Debug: }
Mon Nov 12 11:04:40 2018 : Debug: }
Mon Nov 12 11:04:40 2018 : Debug: XLAT-ELSE {
Mon Nov 12 11:04:40 2018 : Debug: literal --> EXAMPLEDOM
Mon Nov 12 11:04:40 2018 : Debug: }
Mon Nov 12 11:04:40 2018 : ERROR: (1) mschap: No NT-Domain was found in the User-Name
Mon Nov 12 11:04:40 2018 : Debug: (1) mschap: EXPAND --domain=%{%{mschap:NT-Domain}:-EXAMPLEDOM}
Mon Nov 12 11:04:40 2018 : Debug: (1) mschap: --> --domain=EXAMPLEDOM
Mon Nov 12 11:04:40 2018 : Debug: --challenge=%{mschap:Challenge:-00}
Mon Nov 12 11:04:40 2018 : Debug: Parsed xlat tree:
Mon Nov 12 11:04:40 2018 : Debug: literal --> --challenge=
Mon Nov 12 11:04:40 2018 : Debug: xlat --> mschap
Mon Nov 12 11:04:40 2018 : Debug: {
Mon Nov 12 11:04:40 2018 : Debug: literal --> Challenge:-00
Mon Nov 12 11:04:40 2018 : Debug: }
Mon Nov 12 11:04:40 2018 : Debug: (1) mschap: Creating challenge hash with username: johndoe:123456
Mon Nov 12 11:04:40 2018 : Debug: (1) mschap: EXPAND --challenge=%{mschap:Challenge:-00}
Mon Nov 12 11:04:40 2018 : Debug: (1) mschap: --> --challenge=d64fcfdbedcc33ee
Mon Nov 12 11:04:40 2018 : Debug: --nt-response=%{mschap:NT-Response:-00}
Mon Nov 12 11:04:40 2018 : Debug: Parsed xlat tree:
Mon Nov 12 11:04:40 2018 : Debug: literal --> --nt-response=
Mon Nov 12 11:04:40 2018 : Debug: xlat --> mschap
Mon Nov 12 11:04:40 2018 : Debug: {
Mon Nov 12 11:04:40 2018 : Debug: literal --> NT-Response:-00
Mon Nov 12 11:04:40 2018 : Debug: }
Mon Nov 12 11:04:40 2018 : Debug: (1) mschap: EXPAND --nt-response=%{mschap:NT-Response:-00}
Mon Nov 12 11:04:40 2018 : Debug: (1) mschap: --> --nt-response=4caa9abd0548379b7e274a01c7faf807a7be4b3f16980725
Mon Nov 12 11:04:40 2018 : Debug: (1) mschap: Program returned code (0) and output 'NT_KEY: B18DE605DA0547E15B2F27CEBA5CEBB1'
Mon Nov 12 11:04:40 2018 : Debug: (1) mschap: Adding MS-CHAPv2 MPPE keys
Mon Nov 12 11:04:40 2018 : Debug: (1) modsingle[authenticate]: returned from mschap (rlm_mschap)
Mon Nov 12 11:04:40 2018 : Debug: (1) [mschap] = ok
Mon Nov 12 11:04:40 2018 : Debug: (1) } # authenticate = ok
Mon Nov 12 11:04:40 2018 : Debug: (1) MSCHAP Success
Mon Nov 12 11:04:40 2018 : Debug: (1) eap: Sending EAP Request (code 1) ID 2 length 51
Mon Nov 12 11:04:40 2018 : Debug: (1) eap: EAP session adding &reply:State = 0xfb6bfe4bfa69e43b
Mon Nov 12 11:04:40 2018 : Debug: (1) modsingle[authenticate]: returned from eap (rlm_eap)
Mon Nov 12 11:04:40 2018 : Debug: (1) [eap] = handled
Mon Nov 12 11:04:40 2018 : Debug: (1) } # if (ok) = handled
Mon Nov 12 11:04:40 2018 : Debug: (1) } # Auth-Type PAP = handled
Mon Nov 12 11:04:40 2018 : Debug: (1) Using Post-Auth-Type Challenge
Mon Nov 12 11:04:40 2018 : Debug: (1) # Executing group from file /etc/raddb/sites-enabled/default
Mon Nov 12 11:04:40 2018 : Debug: (1) Challenge { ... } # empty sub-section is ignored
Mon Nov 12 11:04:40 2018 : Debug: (1) session-state: Nothing to cache
Mon Nov 12 11:04:40 2018 : Debug: (1) Sent Access-Challenge Id 9 from 192.168.1.100:1812 to 192.168.2.100:58006 length 0
Mon Nov 12 11:04:40 2018 : Debug: (1) EAP-Message = 0x010200331a0301002e533d31454643303335343134334238423145433843363138443039453534433946453631373032333434
Mon Nov 12 11:04:40 2018 : Debug: (1) Message-Authenticator = 0x00000000000000000000000000000000
Mon Nov 12 11:04:40 2018 : Debug: (1) State = 0xfb6bfe4bfa69e43b45f5a1d5430de6d2
Mon Nov 12 11:04:40 2018 : Debug: (1) Finished request
Mon Nov 12 11:04:40 2018 : Debug: Waking up in 4.9 seconds.
Mon Nov 12 11:04:40 2018 : Debug: (2) Received Access-Request Id 10 from 192.168.2.100:58006 to 192.168.1.100:1812 length 169
Mon Nov 12 11:04:40 2018 : Debug: (2) User-Name = "johndoe:123456"
Mon Nov 12 11:04:40 2018 : Debug: (2) NAS-Port-Type = Virtual
Mon Nov 12 11:04:40 2018 : Debug: (2) Service-Type = Framed-User
Mon Nov 12 11:04:40 2018 : Debug: (2) NAS-Port = 5
Mon Nov 12 11:04:40 2018 : Debug: (2) NAS-Port-Id = "con2"
Mon Nov 12 11:04:40 2018 : Debug: (2) NAS-IP-Address = 188.188.188.188
Mon Nov 12 11:04:40 2018 : Debug: (2) Called-Station-Id = "188.188.188.188[4500]"
Mon Nov 12 11:04:40 2018 : Debug: (2) Calling-Station-Id = "66.66.66.66[4500]"
Mon Nov 12 11:04:40 2018 : Debug: (2) EAP-Message = 0x020200061a03
Mon Nov 12 11:04:40 2018 : Debug: (2) NAS-Identifier = "strongSwan"
Mon Nov 12 11:04:40 2018 : Debug: (2) State = 0xfb6bfe4bfa69e43b45f5a1d5430de6d2
Mon Nov 12 11:04:40 2018 : Debug: (2) Message-Authenticator = 0x654b4205c000cb7eab5e5262156d5ca8
Mon Nov 12 11:04:40 2018 : Debug: (2) session-state: No cached attributes
Mon Nov 12 11:04:40 2018 : Debug: (2) # Executing section authorize from file /etc/raddb/sites-enabled/default
Mon Nov 12 11:04:40 2018 : Debug: (2) authorize {
Mon Nov 12 11:04:40 2018 : Debug: (2) if ( &User-Name =~ /^(.*):([0-9]{6})$/) {
Mon Nov 12 11:04:40 2018 : Debug: No matches
Mon Nov 12 11:04:40 2018 : Debug: Adding 3 matches
Mon Nov 12 11:04:40 2018 : Debug: (2) if ( &User-Name =~ /^(.*):([0-9]{6})$/) -> TRUE
Mon Nov 12 11:04:40 2018 : Debug: (2) if ( &User-Name =~ /^(.*):([0-9]{6})$/) {
Mon Nov 12 11:04:40 2018 : Debug: (2) update request {
Mon Nov 12 11:04:40 2018 : Debug: (2) 1/3 Found: johndoe (14)
Mon Nov 12 11:04:40 2018 : Debug: (2) EXPAND %{1}
Mon Nov 12 11:04:40 2018 : Debug: (2) --> johndoe
Mon Nov 12 11:04:40 2018 : Debug: (2) Stripped-User-Name := johndoe
Mon Nov 12 11:04:40 2018 : Debug: (2) 2/3 Found: 123456 (7)
Mon Nov 12 11:04:40 2018 : Debug: (2) EXPAND %{2}
Mon Nov 12 11:04:40 2018 : Debug: (2) --> 123456
Mon Nov 12 11:04:40 2018 : Debug: (2) User-OTP := 123456
Mon Nov 12 11:04:40 2018 : Debug: (2) } # update request = noop
Mon Nov 12 11:04:40 2018 : Debug: (2) } # if ( &User-Name =~ /^(.*):([0-9]{6})$/) = noop
Mon Nov 12 11:04:40 2018 : Debug: (2) modsingle[authorize]: calling preprocess (rlm_preprocess)
Mon Nov 12 11:04:40 2018 : Debug: (2) modsingle[authorize]: returned from preprocess (rlm_preprocess)
Mon Nov 12 11:04:40 2018 : Debug: (2) [preprocess] = ok
Mon Nov 12 11:04:40 2018 : Debug: (2) modsingle[authorize]: calling files (rlm_files)
Mon Nov 12 11:04:40 2018 : Debug: %{%{Stripped-User-Name}:-%{User-Name}}
Mon Nov 12 11:04:40 2018 : Debug: Parsed xlat tree:
Mon Nov 12 11:04:40 2018 : Debug: XLAT-IF {
Mon Nov 12 11:04:40 2018 : Debug: attribute --> Stripped-User-Name
Mon Nov 12 11:04:40 2018 : Debug: }
Mon Nov 12 11:04:40 2018 : Debug: XLAT-ELSE {
Mon Nov 12 11:04:40 2018 : Debug: attribute --> User-Name
Mon Nov 12 11:04:40 2018 : Debug: }
Mon Nov 12 11:04:40 2018 : Debug: (2) files: EXPAND %{%{Stripped-User-Name}:-%{User-Name}}
Mon Nov 12 11:04:40 2018 : Debug: (2) files: --> johndoe
Mon Nov 12 11:04:40 2018 : Debug: (2) files: users: Matched entry johndoe at line 4
Mon Nov 12 11:04:40 2018 : Debug: (2) files: ::: FROM 0 TO 0 MAX 0
Mon Nov 12 11:04:40 2018 : Debug: (2) files: ::: TO in 0 out 0
Mon Nov 12 11:04:40 2018 : Debug: (2) modsingle[authorize]: returned from files (rlm_files)
Mon Nov 12 11:04:40 2018 : Debug: (2) [files] = ok
Mon Nov 12 11:04:40 2018 : Debug: (2) modsingle[authorize]: calling expiration (rlm_expiration)
Mon Nov 12 11:04:40 2018 : Debug: (2) modsingle[authorize]: returned from expiration (rlm_expiration)
Mon Nov 12 11:04:40 2018 : Debug: (2) [expiration] = noop
Mon Nov 12 11:04:40 2018 : Debug: (2) modsingle[authorize]: calling logintime (rlm_logintime)
Mon Nov 12 11:04:40 2018 : Debug: (2) modsingle[authorize]: returned from logintime (rlm_logintime)
Mon Nov 12 11:04:40 2018 : Debug: (2) [logintime] = noop
Mon Nov 12 11:04:40 2018 : Debug: (2) modsingle[authorize]: calling pap (rlm_pap)
Mon Nov 12 11:04:40 2018 : Debug: (2) modsingle[authorize]: returned from pap (rlm_pap)
Mon Nov 12 11:04:40 2018 : Debug: (2) [pap] = updated
Mon Nov 12 11:04:40 2018 : Debug: (2) } # authorize = updated
Mon Nov 12 11:04:40 2018 : Debug: (2) Found Auth-Type = PAP
Mon Nov 12 11:04:40 2018 : Debug: (2) # Executing group from file /etc/raddb/sites-enabled/default
Mon Nov 12 11:04:40 2018 : Debug: (2) Auth-Type PAP {
Mon Nov 12 11:04:40 2018 : Debug: (2) modsingle[authenticate]: calling pap (rlm_pap)
Mon Nov 12 11:04:40 2018 : Debug: (2) pap: Login attempt with password "123456" (6)
Mon Nov 12 11:04:40 2018 : Debug: (2) pap: Comparing with "known good" Cleartext-Password "123456" (6)
Mon Nov 12 11:04:40 2018 : Debug: (2) pap: User authenticated successfully
Mon Nov 12 11:04:40 2018 : Debug: (2) modsingle[authenticate]: returned from pap (rlm_pap)
Mon Nov 12 11:04:40 2018 : Debug: (2) [pap] = ok
Mon Nov 12 11:04:40 2018 : Debug: (2) if (ok) {
Mon Nov 12 11:04:40 2018 : Debug: (2) if (ok) -> TRUE
Mon Nov 12 11:04:40 2018 : Debug: (2) if (ok) {
Mon Nov 12 11:04:40 2018 : Debug: (2) modsingle[authenticate]: calling eap (rlm_eap)
Mon Nov 12 11:04:40 2018 : Debug: (2) eap: Expiring EAP session with state 0xfb6bfe4bfa69e43b
Mon Nov 12 11:04:40 2018 : Debug: (2) eap: Finished EAP session with state 0xfb6bfe4bfa69e43b
Mon Nov 12 11:04:40 2018 : Debug: (2) eap: Previous EAP request found for state 0xfb6bfe4bfa69e43b, released from the list
Mon Nov 12 11:04:40 2018 : Debug: (2) eap: Peer sent packet with method EAP MSCHAPv2 (26)
Mon Nov 12 11:04:40 2018 : Debug: (2) eap: Calling submodule eap_mschapv2 to process data
Mon Nov 12 11:04:40 2018 : Debug: (2) eap: Sending EAP Success (code 3) ID 2 length 4
Mon Nov 12 11:04:40 2018 : Debug: (2) eap: Freeing handler
Mon Nov 12 11:04:40 2018 : Debug: (2) modsingle[authenticate]: returned from eap (rlm_eap)
Mon Nov 12 11:04:40 2018 : Debug: (2) [eap] = ok
Mon Nov 12 11:04:40 2018 : Debug: (2) } # if (ok) = ok
Mon Nov 12 11:04:40 2018 : Debug: (2) } # Auth-Type PAP = ok
Mon Nov 12 11:04:40 2018 : Debug: (2) # Executing section post-auth from file /etc/raddb/sites-enabled/default
Mon Nov 12 11:04:40 2018 : Debug: (2) post-auth {
Mon Nov 12 11:04:40 2018 : Debug: (2) update {
Mon Nov 12 11:04:40 2018 : Debug: (2) No attributes updated
Mon Nov 12 11:04:40 2018 : Debug: (2) } # update = noop
Mon Nov 12 11:04:40 2018 : Debug: (2) modsingle[post-auth]: calling exec (rlm_exec)
Mon Nov 12 11:04:40 2018 : Debug: (2) modsingle[post-auth]: returned from exec (rlm_exec)
Mon Nov 12 11:04:40 2018 : Debug: (2) [exec] = noop
Mon Nov 12 11:04:40 2018 : Debug: (2) policy remove_reply_message_if_eap {
Mon Nov 12 11:04:40 2018 : Debug: (2) if (&reply:EAP-Message && &reply:Reply-Message) {
Mon Nov 12 11:04:40 2018 : Debug: (2) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE
Mon Nov 12 11:04:40 2018 : Debug: (2) else {
Mon Nov 12 11:04:40 2018 : Debug: (2) modsingle[post-auth]: calling noop (rlm_always)
Mon Nov 12 11:04:40 2018 : Debug: (2) modsingle[post-auth]: returned from noop (rlm_always)
Mon Nov 12 11:04:40 2018 : Debug: (2) [noop] = noop
Mon Nov 12 11:04:40 2018 : Debug: (2) } # else = noop
Mon Nov 12 11:04:40 2018 : Debug: (2) } # policy remove_reply_message_if_eap = noop
Mon Nov 12 11:04:40 2018 : Debug: (2) } # post-auth = noop
Mon Nov 12 11:04:40 2018 : Debug: (2) Sent Access-Accept Id 10 from 192.168.1.100:1812 to 192.168.2.100:58006 length 0
Mon Nov 12 11:04:40 2018 : Debug: (2) MS-MPPE-Encryption-Policy = Encryption-Required
Mon Nov 12 11:04:40 2018 : Debug: (2) MS-MPPE-Encryption-Types = RC4-40or128-bit-Allowed
Mon Nov 12 11:04:40 2018 : Debug: (2) MS-MPPE-Send-Key = 0xcbf551f76a44f29550c2e6bccd4e256c
Mon Nov 12 11:04:40 2018 : Debug: (2) MS-MPPE-Recv-Key = 0xd85d1854dee9755637e77e927291eec4
Mon Nov 12 11:04:40 2018 : Debug: (2) EAP-Message = 0x03020004
Mon Nov 12 11:04:40 2018 : Debug: (2) Message-Authenticator = 0x00000000000000000000000000000000
Mon Nov 12 11:04:40 2018 : Debug: (2) Finished request
Mon Nov 12 11:04:40 2018 : Debug: Waking up in 4.9 seconds.
Am Montag, November 12, 2018 10:27 CET, Adam Bishop <Adam.Bishop at jisc.ac.uk> schrieb:
On 11 Nov 2018, at 20:56, Markus Maurer <lists at v-net.tk> wrote:
> Hmm... Meanwhile I think that you didn‘t understand the problem. You’re just talking around the problem, not about the problem neither trying to help solving it...
I'm reasonably sure the maintainer of the server has a better idea of how it works than yourself.
> The nt hash is calculated from the password, not from the username
That's 100% correct, but unfortunately 100% unrelated.
MSCHAP uses the username to create the *challenge hash* not the *NT hash*. If you change the username, the authentication process fails because you've changed the challenge hash.
You *cannot* make this work using MSCHAP and AD.
If you want to use OTP you have to change EAP method, or as Alan told you several messages ago, store clear text passwords.
Adam Bishop
gpg: E75B 1F92 6407 DFDF 9F1C BF10 C993 2504 6609 D460
jisc.ac.uk
Jisc is a registered charity (number 1149740) and a company limited by guarantee which is registered in England under Company No. 5747339, VAT No. GB 197 0632 86. Jisc’s registered office is: One Castlepark, Tower Hill, Bristol, BS2 0JA. T 0203 697 5800.
Jisc Services Limited is a wholly owned Jisc subsidiary and a company limited by guarantee which is registered in England under company number 2881024, VAT number GB 197 0632 86. The registered office is: One Castle Park, Tower Hill, Bristol BS2 0JA. T 0203 697 5800.
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
--
This email was Malware checked by UTM 9. http://www.sophos.com
More information about the Freeradius-Users
mailing list