Re: Sending Access-Challenge instead of Access-Accept using MS-CHAPv2

13 Mar 2017

      This is the response I got from Cisco:

_________________

Thank you for the very detailed instructions. I was able to reproduce the
issue and I believe that freeradius is violating rfc2548 section 2.3.3:

2.3.3.  MS-CHAP2-Success

   Description

      This Attribute contains a 42-octet authenticator response string.

      This string MUST be included in the Message field of the MS-CHAP-

      V2 Success packet sent from the NAS to the peer.  This Attribute

      is only used in Access-Accept packets.

In the packet capture I can see that the Access-Challenge contains
“MS-CHAP2-Success” attribute.

I have found a similar case and it looks like ASA is expecting
MS-CHAP2-Success along with proper Authenticator in the Access-Accept
message in order to properly validate the RADIUS exchange.

Unfortunately, I have no idea how to reconfigure the FreeRadius to conform
to this requirement.

_________________

This is my output:
Received Access-Request Id 164 from 172.28.0.18:63103 to 10.58.0.15:1812
length 241
        User-Name = 'k00jlod'
        NAS-Port = 27713536
        Called-Station-Id = '82.147.36.212'
        Calling-Station-Id = '77.106.182.238'
        NAS-Port-Type = Virtual
        Tunnel-Client-Endpoint:0 = '77.106.182.238'
        MS-CHAP-Challenge = 0x8739b036b944ff2f3f7cba701f3e841b
        MS-CHAP2-Response =
0x0000d6e0d53088952eadf04f9f0bcc07babb0000000000000000a4f05481ea47278d26d47d8f0f2ccd36235ece255201258f
        NAS-IP-Address = 172.28.0.18
        Cisco-AVPair = 'ip:source-ip=77.106.182.238'
        ASA-TunnelGroupName = 'Two-factor'
        ASA-ClientType = AnyConnect-Client-SSL-VPN
Mon Mar 13 12:27:10 2017 : Debug: (1) Received Access-Request packet from
host 172.28.0.18 port 63103, id=164, length=241
Mon Mar 13 12:27:10 2017 : Debug: (1)   User-Name = 'k00jlod'
Mon Mar 13 12:27:10 2017 : Debug: (1)   NAS-Port = 27713536
Mon Mar 13 12:27:10 2017 : Debug: (1)   Called-Station-Id = '82.147.36.212'
Mon Mar 13 12:27:10 2017 : Debug: (1)   Calling-Station-Id =
'77.106.182.238'
Mon Mar 13 12:27:10 2017 : Debug: (1)   NAS-Port-Type = Virtual
Mon Mar 13 12:27:10 2017 : Debug: (1)   Tunnel-Client-Endpoint:0 =
'77.106.182.238'
Mon Mar 13 12:27:10 2017 : Debug: (1)   MS-CHAP-Challenge =
0x8739b036b944ff2f3f7cba701f3e841b
Mon Mar 13 12:27:10 2017 : Debug: (1)   MS-CHAP2-Response =
0x0000d6e0d53088952eadf04f9f0bcc07babb0000000000000000a4f05481ea47278d26d47d8f0f2ccd36235ece255201258f
Mon Mar 13 12:27:10 2017 : Debug: (1)   NAS-IP-Address = 172.28.0.18
Mon Mar 13 12:27:10 2017 : Debug: (1)   Cisco-AVPair =
'ip:source-ip=77.106.182.238'
Mon Mar 13 12:27:10 2017 : Debug: (1)   ASA-TunnelGroupName = 'Two-factor'
Mon Mar 13 12:27:10 2017 : Debug: (1)   ASA-ClientType =
AnyConnect-Client-SSL-VPN
Mon Mar 13 12:27:10 2017 : Debug: (1) # Executing section authorize from
file /etc/raddb/sites-enabled/default
Mon Mar 13 12:27:10 2017 : Debug: (1)   authorize {
Mon Mar 13 12:27:10 2017 : Debug: (1)   filter_username filter_username {
Mon Mar 13 12:27:10 2017 : Debug: (1)     if (!&User-Name)
Mon Mar 13 12:27:10 2017 : Debug: (1)     if (!&User-Name)  -> FALSE
Mon Mar 13 12:27:10 2017 : Debug: (1)     if (&User-Name =~ / /)
Mon Mar 13 12:27:10 2017 : Debug: (1)     if (&User-Name =~ / /)  -> FALSE
Mon Mar 13 12:27:10 2017 : Debug: (1)     if (&User-Name =~ /@.*@/ )
Mon Mar 13 12:27:10 2017 : Debug: (1)     if (&User-Name =~ /@.*@/ )  ->
FALSE
Mon Mar 13 12:27:10 2017 : Debug: (1)     if (&User-Name =~ /\\.\\./ )
Mon Mar 13 12:27:10 2017 : Debug: (1)     if (&User-Name =~ /\\.\\./ )  ->
FALSE
Mon Mar 13 12:27:10 2017 : Debug: (1)     if ((&User-Name =~ /@/) &&
(&User-Name !~ /@(.+)\\.(.+)$/))
Mon Mar 13 12:27:10 2017 : Debug: (1)     if ((&User-Name =~ /@/) &&
(&User-Name !~ /@(.+)\\.(.+)$/))   -> FALSE
Mon Mar 13 12:27:10 2017 : Debug: (1)     if (&User-Name =~ /\\.$/)
Mon Mar 13 12:27:10 2017 : Debug: (1)     if (&User-Name =~ /\\.$/)   ->
FALSE
Mon Mar 13 12:27:10 2017 : Debug: (1)     if (&User-Name =~ /@\\./)
Mon Mar 13 12:27:10 2017 : Debug: (1)     if (&User-Name =~ /@\\./)   ->
FALSE
Mon Mar 13 12:27:10 2017 : Debug: (1)   } # filter_username filter_username
= notfound
Mon Mar 13 12:27:10 2017 : Debug: (1)  modsingle[authorize]: calling
preprocess (rlm_preprocess) for request 1
Mon Mar 13 12:27:10 2017 : Debug: (1) modsingle[authorize]: returned from
preprocess (rlm_preprocess) for request 1
Mon Mar 13 12:27:10 2017 : Debug: (1)   [preprocess] = ok
Mon Mar 13 12:27:10 2017 : Debug: (1)    if (State)
Mon Mar 13 12:27:10 2017 : Debug: (1)    if (State)  -> FALSE
Mon Mar 13 12:27:10 2017 : Debug: (1)  modsingle[authorize]: calling chap
(rlm_chap) for request 1
Mon Mar 13 12:27:10 2017 : Debug: (1) modsingle[authorize]: returned from
chap (rlm_chap) for request 1
Mon Mar 13 12:27:10 2017 : Debug: (1)   [chap] = noop
Mon Mar 13 12:27:10 2017 : Debug: (1)  modsingle[authorize]: calling mschap
(rlm_mschap) for request 1
Mon Mar 13 12:27:10 2017 : Debug: (1)  mschap : Found MS-CHAP attributes.
Setting 'Auth-Type  = mschap'
Mon Mar 13 12:27:10 2017 : Debug: (1) modsingle[authorize]: returned from
mschap (rlm_mschap) for request 1
Mon Mar 13 12:27:10 2017 : Debug: (1)   [mschap] = ok
Mon Mar 13 12:27:10 2017 : Debug: (1)  modsingle[authorize]: calling digest
(rlm_digest) for request 1
Mon Mar 13 12:27:10 2017 : Debug: (1) modsingle[authorize]: returned from
digest (rlm_digest) for request 1
Mon Mar 13 12:27:10 2017 : Debug: (1)   [digest] = noop
Mon Mar 13 12:27:10 2017 : Debug: (1)  modsingle[authorize]: calling suffix
(rlm_realm) for request 1
Mon Mar 13 12:27:10 2017 : Debug: (1)  suffix : Checking for suffix after
"@"
Mon Mar 13 12:27:10 2017 : Debug: (1)  suffix : No '@' in User-Name =
"k00jlod", looking up realm NULL
Mon Mar 13 12:27:10 2017 : Debug: (1)  suffix : No such realm "NULL"
Mon Mar 13 12:27:10 2017 : Debug: (1) modsingle[authorize]: returned from
suffix (rlm_realm) for request 1
Mon Mar 13 12:27:10 2017 : Debug: (1)   [suffix] = noop
Mon Mar 13 12:27:10 2017 : Debug: (1)  modsingle[authorize]: calling eap
(rlm_eap) for request 1
Mon Mar 13 12:27:10 2017 : Debug: (1)  eap : No EAP-Message, not doing EAP
Mon Mar 13 12:27:10 2017 : Debug: (1) modsingle[authorize]: returned from
eap (rlm_eap) for request 1
Mon Mar 13 12:27:10 2017 : Debug: (1)   [eap] = noop
Mon Mar 13 12:27:10 2017 : Debug: (1)  modsingle[authorize]: calling files
(rlm_files) for request 1
Mon Mar 13 12:27:10 2017 : Debug: (1) modsingle[authorize]: returned from
files (rlm_files) for request 1
Mon Mar 13 12:27:10 2017 : Debug: (1)   [files] = noop
Mon Mar 13 12:27:10 2017 : Debug: (1)  modsingle[authorize]: calling
expiration (rlm_expiration) for request 1
Mon Mar 13 12:27:10 2017 : Debug: (1) modsingle[authorize]: returned from
expiration (rlm_expiration) for request 1
Mon Mar 13 12:27:10 2017 : Debug: (1)   [expiration] = noop
Mon Mar 13 12:27:10 2017 : Debug: (1)  modsingle[authorize]: calling
logintime (rlm_logintime) for request 1
Mon Mar 13 12:27:10 2017 : Debug: (1) modsingle[authorize]: returned from
logintime (rlm_logintime) for request 1
Mon Mar 13 12:27:10 2017 : Debug: (1)   [logintime] = noop
Mon Mar 13 12:27:10 2017 : Debug: (1)  modsingle[authorize]: calling pap
(rlm_pap) for request 1
Mon Mar 13 12:27:10 2017 : WARNING: (1)  pap : No "known good" password
found for the user.  Not setting Auth-Type
Mon Mar 13 12:27:10 2017 : WARNING: (1)  pap : Authentication will fail
unless a "known good" password is available
Mon Mar 13 12:27:10 2017 : Debug: (1) modsingle[authorize]: returned from
pap (rlm_pap) for request 1
Mon Mar 13 12:27:10 2017 : Debug: (1)   [pap] = noop
Mon Mar 13 12:27:10 2017 : Debug: (1)  } #  authorize = ok
Mon Mar 13 12:27:10 2017 : Debug: (1) Found Auth-Type = MSCHAP
Mon Mar 13 12:27:10 2017 : Debug: (1) # Executing group from file
/etc/raddb/sites-enabled/default
Mon Mar 13 12:27:10 2017 : Debug: (1)  Auth-Type MS-CHAP {
Mon Mar 13 12:27:10 2017 : Debug: (1)  modsingle[authenticate]: calling
mschap (rlm_mschap) for request 1
Mon Mar 13 12:27:10 2017 : Debug: (1)  mschap : Creating challenge hash
with username: k00jlod
Mon Mar 13 12:27:10 2017 : Debug: (1)  mschap : Client is using MS-CHAPv2
Mon Mar 13 12:27:10 2017 : Debug: Executing: /usr/bin/ntlm_auth
--request-nt-key --username=%{mschap:User-Name}
--challenge=%{%{mschap:Challenge}:-00}
--nt-response=%{%{mschap:NT-Response}:-00} --domain=%{mschap:NT-Domain}:
Mon Mar 13 12:27:10 2017 : Debug: --username=%{mschap:User-Name}
Mon Mar 13 12:27:10 2017 : Debug: Parsed xlat tree:
Mon Mar 13 12:27:10 2017 : Debug: literal --> --username=
Mon Mar 13 12:27:10 2017 : Debug: xlat --> mschap
Mon Mar 13 12:27:10 2017 : Debug: {
Mon Mar 13 12:27:10 2017 : Debug:       literal --> User-Name
Mon Mar 13 12:27:10 2017 : Debug: }
Mon Mar 13 12:27:10 2017 : Debug: (1)  mschap : EXPAND
--username=%{mschap:User-Name}
Mon Mar 13 12:27:10 2017 : Debug: (1)  mschap :    --> --username=k00jlod
Mon Mar 13 12:27:10 2017 : Debug: --challenge=%{%{mschap:Challenge}:-00}
Mon Mar 13 12:27:10 2017 : Debug: Parsed xlat tree:
Mon Mar 13 12:27:10 2017 : Debug: literal --> --challenge=
Mon Mar 13 12:27:10 2017 : Debug: if {
Mon Mar 13 12:27:10 2017 : Debug:       xlat --> mschap
Mon Mar 13 12:27:10 2017 : Debug:       {
Mon Mar 13 12:27:10 2017 : Debug:               literal --> Challenge
Mon Mar 13 12:27:10 2017 : Debug:       }
Mon Mar 13 12:27:10 2017 : Debug: }
Mon Mar 13 12:27:10 2017 : Debug: else {
Mon Mar 13 12:27:10 2017 : Debug:       literal --> 00
Mon Mar 13 12:27:10 2017 : Debug: }
Mon Mar 13 12:27:10 2017 : Debug: (1)  mschap : Creating challenge hash
with username: k00jlod
Mon Mar 13 12:27:10 2017 : Debug: (1)  mschap : EXPAND
--challenge=%{%{mschap:Challenge}:-00}
Mon Mar 13 12:27:10 2017 : Debug: (1)  mschap :    -->
--challenge=5be157fe7659ba10
Mon Mar 13 12:27:10 2017 : Debug: --nt-response=%{%{mschap:NT-Response}:-00}
Mon Mar 13 12:27:10 2017 : Debug: Parsed xlat tree:
Mon Mar 13 12:27:10 2017 : Debug: literal --> --nt-response=
Mon Mar 13 12:27:10 2017 : Debug: if {
Mon Mar 13 12:27:10 2017 : Debug:       xlat --> mschap
Mon Mar 13 12:27:10 2017 : Debug:       {
Mon Mar 13 12:27:10 2017 : Debug:               literal --> NT-Response
Mon Mar 13 12:27:10 2017 : Debug:       }
Mon Mar 13 12:27:10 2017 : Debug: }
Mon Mar 13 12:27:10 2017 : Debug: else {
Mon Mar 13 12:27:10 2017 : Debug:       literal --> 00
Mon Mar 13 12:27:10 2017 : Debug: }
Mon Mar 13 12:27:10 2017 : Debug: (1)  mschap : EXPAND
--nt-response=%{%{mschap:NT-Response}:-00}
Mon Mar 13 12:27:10 2017 : Debug: (1)  mschap :    -->
--nt-response=a4f05481ea47278d26d47d8f0f2ccd36235ece255201258f
Mon Mar 13 12:27:10 2017 : Debug: --domain=%{mschap:NT-Domain}
Mon Mar 13 12:27:10 2017 : Debug: Parsed xlat tree:
Mon Mar 13 12:27:10 2017 : Debug: literal --> --domain=
Mon Mar 13 12:27:10 2017 : Debug: xlat --> mschap
Mon Mar 13 12:27:10 2017 : Debug: {
Mon Mar 13 12:27:10 2017 : Debug:       literal --> NT-Domain
Mon Mar 13 12:27:10 2017 : Debug: }
Mon Mar 13 12:27:10 2017 : ERROR: (1)  mschap : No NT-Domain was found in
the User-Name
Mon Mar 13 12:27:10 2017 : Debug: (1)  mschap : EXPAND
--domain=%{mschap:NT-Domain}
Mon Mar 13 12:27:10 2017 : Debug: (1)  mschap :    --> --domain=
Mon Mar 13 12:27:10 2017 : Debug: Program returned code (0) and output
'NT_KEY: 726FA77A206B0A0055EA8EC04BA5C7A8'
Mon Mar 13 12:27:10 2017 : Debug: (1)  mschap : Adding MS-CHAPv2 MPPE keys
Mon Mar 13 12:27:10 2017 : Debug: (1) modsingle[authenticate]: returned
from mschap (rlm_mschap) for request 1
Mon Mar 13 12:27:10 2017 : Debug: (1)   [mschap] = ok
Mon Mar 13 12:27:10 2017 : Debug: (1)   challenge challenge {
Mon Mar 13 12:27:10 2017 : Debug: (1)    update control {
Mon Mar 13 12:27:10 2017 : Debug: (1)   &Response-Packet-Type =
Access-Challenge
Mon Mar 13 12:27:10 2017 : Debug: (1)    } # update control = noop
Mon Mar 13 12:27:10 2017 : Debug: (1)    update reply {
Mon Mar 13 12:27:10 2017 : Debug: (1)   &Reply-Message = 'Tast inn din
engangskode.\n\nOm du ikke er registrert for sterk autentisering, kan dette
gjøres på nettsiden https://id.hedmark.org'
Mon Mar 13 12:27:10 2017 : Debug: (1) EXPAND %{randstr:nnnnnnnn}
Mon Mar 13 12:27:10 2017 : Debug: (1)    --> 43934796
Mon Mar 13 12:27:10 2017 : Debug: (1)   &State = 0x3433393334373936
Mon Mar 13 12:27:10 2017 : Debug: (1)    } # update reply = noop
Mon Mar 13 12:27:10 2017 : Debug: (1)  modsingle[authenticate]: calling
handled (rlm_always) for request 1
Mon Mar 13 12:27:10 2017 : Debug: (1) modsingle[authenticate]: returned
from handled (rlm_always) for request 1
Mon Mar 13 12:27:10 2017 : Debug: (1)    [handled] = handled
Mon Mar 13 12:27:10 2017 : Debug: (1)   } # challenge challenge = handled
Mon Mar 13 12:27:10 2017 : Debug: (1)  } # Auth-Type MS-CHAP = handled
Mon Mar 13 12:27:10 2017 : Debug: (1) Sending Access-Challenge packet to
host 172.28.0.18 port 63103, id=164, length=0
Mon Mar 13 12:27:10 2017 : Debug: (1)   MS-CHAP2-Success =
0x00533d42333944423243394234453931304238454145414438444543314339353330333834343641313339
Mon Mar 13 12:27:10 2017 : Debug: (1)   MS-MPPE-Recv-Key =
0x64f6fa51e30f7267fb3785e2061c501d
Mon Mar 13 12:27:10 2017 : Debug: (1)   MS-MPPE-Send-Key =
0xefe9c04f5d551895ab42cef20b8767a2
Mon Mar 13 12:27:10 2017 : Debug: (1)   MS-MPPE-Encryption-Policy =
Encryption-Allowed
Mon Mar 13 12:27:10 2017 : Debug: (1)   MS-MPPE-Encryption-Types =
RC4-40or128-bit-Allowed
Mon Mar 13 12:27:10 2017 : Debug: (1)   Reply-Message = 'Tast inn din
engangskode.\n\nOm du ikke er registrert for sterk autentisering, kan dette
gjøres på nettsiden https://id.hedmark.org'
Mon Mar 13 12:27:10 2017 : Debug: (1)   State = 0x3433393334373936
Sending Access-Challenge Id 164 from 10.58.0.15:1812 to 172.28.0.18:63103
        MS-CHAP2-Success =
0x00533d42333944423243394234453931304238454145414438444543314339353330333834343641313339
        MS-MPPE-Recv-Key = 0x64f6fa51e30f7267fb3785e2061c501d
        MS-MPPE-Send-Key = 0xefe9c04f5d551895ab42cef20b8767a2
        MS-MPPE-Encryption-Policy = Encryption-Allowed
        MS-MPPE-Encryption-Types = RC4-40or128-bit-Allowed
        Reply-Message = 'Tast inn din engangskode.\n\nOm du ikke er
registrert for sterk autentisering, kan dette gjøres på nettsiden
https://id.hedmark.org'
        State = 0x3433393334373936
Mon Mar 13 12:27:10 2017 : Debug: (1) Finished request
Mon Mar 13 12:27:10 2017 : Debug: Waking up in 0.2 seconds.
Mon Mar 13 12:27:11 2017 : Debug: Waking up in 4.7 seconds.
Mon Mar 13 12:27:15 2017 : Debug: (1) Cleaning up request packet ID 164
with timestamp +101
Mon Mar 13 12:27:15 2017 : Info: Ready to process requests
Received Access-Request Id 165 from 172.28.0.18:63103 to 10.58.0.15:1812
length 187
        User-Name = 'k00jlod'
        User-Password = '876274'
        NAS-Port = 27713536
        Called-Station-Id = '82.147.36.212'
        Calling-Station-Id = '77.106.182.238'
        NAS-Port-Type = Virtual
        Tunnel-Client-Endpoint:0 = '77.106.182.238'
        NAS-IP-Address = 172.28.0.18
        State = 0x3433393334373936
        Cisco-AVPair = 'ip:source-ip=77.106.182.238'
        ASA-TunnelGroupName = 'Two-factor'
        ASA-ClientType = AnyConnect-Client-SSL-VPN
Mon Mar 13 12:27:17 2017 : Debug: (2) Received Access-Request packet from
host 172.28.0.18 port 63103, id=165, length=187
Mon Mar 13 12:27:17 2017 : Debug: (2)   User-Name = 'k00jlod'
Mon Mar 13 12:27:17 2017 : Debug: (2)   User-Password = '876274'
Mon Mar 13 12:27:17 2017 : Debug: (2)   NAS-Port = 27713536
Mon Mar 13 12:27:17 2017 : Debug: (2)   Called-Station-Id = '82.147.36.212'
Mon Mar 13 12:27:17 2017 : Debug: (2)   Calling-Station-Id =
'77.106.182.238'
Mon Mar 13 12:27:17 2017 : Debug: (2)   NAS-Port-Type = Virtual
Mon Mar 13 12:27:17 2017 : Debug: (2)   Tunnel-Client-Endpoint:0 =
'77.106.182.238'
Mon Mar 13 12:27:17 2017 : Debug: (2)   NAS-IP-Address = 172.28.0.18
Mon Mar 13 12:27:17 2017 : Debug: (2)   State = 0x3433393334373936
Mon Mar 13 12:27:17 2017 : Debug: (2)   Cisco-AVPair =
'ip:source-ip=77.106.182.238'
Mon Mar 13 12:27:17 2017 : Debug: (2)   ASA-TunnelGroupName = 'Two-factor'
Mon Mar 13 12:27:17 2017 : Debug: (2)   ASA-ClientType =
AnyConnect-Client-SSL-VPN
Mon Mar 13 12:27:17 2017 : Debug: (2) # Executing section authorize from
file /etc/raddb/sites-enabled/default
Mon Mar 13 12:27:17 2017 : Debug: (2)   authorize {
Mon Mar 13 12:27:17 2017 : Debug: (2)   filter_username filter_username {
Mon Mar 13 12:27:17 2017 : Debug: (2)     if (!&User-Name)
Mon Mar 13 12:27:17 2017 : Debug: (2)     if (!&User-Name)  -> FALSE
Mon Mar 13 12:27:17 2017 : Debug: (2)     if (&User-Name =~ / /)
Mon Mar 13 12:27:17 2017 : Debug: (2)     if (&User-Name =~ / /)  -> FALSE
Mon Mar 13 12:27:17 2017 : Debug: (2)     if (&User-Name =~ /@.*@/ )
Mon Mar 13 12:27:17 2017 : Debug: (2)     if (&User-Name =~ /@.*@/ )  ->
FALSE
Mon Mar 13 12:27:17 2017 : Debug: (2)     if (&User-Name =~ /\\.\\./ )
Mon Mar 13 12:27:17 2017 : Debug: (2)     if (&User-Name =~ /\\.\\./ )  ->
FALSE
Mon Mar 13 12:27:17 2017 : Debug: (2)     if ((&User-Name =~ /@/) &&
(&User-Name !~ /@(.+)\\.(.+)$/))
Mon Mar 13 12:27:17 2017 : Debug: (2)     if ((&User-Name =~ /@/) &&
(&User-Name !~ /@(.+)\\.(.+)$/))   -> FALSE
Mon Mar 13 12:27:17 2017 : Debug: (2)     if (&User-Name =~ /\\.$/)
Mon Mar 13 12:27:17 2017 : Debug: (2)     if (&User-Name =~ /\\.$/)   ->
FALSE
Mon Mar 13 12:27:17 2017 : Debug: (2)     if (&User-Name =~ /@\\./)
Mon Mar 13 12:27:17 2017 : Debug: (2)     if (&User-Name =~ /@\\./)   ->
FALSE
Mon Mar 13 12:27:17 2017 : Debug: (2)   } # filter_username filter_username
= notfound
Mon Mar 13 12:27:17 2017 : Debug: (2)  modsingle[authorize]: calling
preprocess (rlm_preprocess) for request 2
Mon Mar 13 12:27:17 2017 : Debug: (2) modsingle[authorize]: returned from
preprocess (rlm_preprocess) for request 2
Mon Mar 13 12:27:17 2017 : Debug: (2)   [preprocess] = ok
Mon Mar 13 12:27:17 2017 : Debug: (2)    if (State)
Mon Mar 13 12:27:17 2017 : Debug: (2)    if (State)  -> TRUE
Mon Mar 13 12:27:17 2017 : Debug: (2)   if (State)  {
Mon Mar 13 12:27:17 2017 : Debug: (2)    update control {
Mon Mar 13 12:27:17 2017 : Debug: (2)   &Auth-Type := perl
Mon Mar 13 12:27:17 2017 : Debug: (2)    } # update control = noop
Mon Mar 13 12:27:17 2017 : Debug: (2)   } # if (State)  = noop
Mon Mar 13 12:27:17 2017 : Debug: (2)  modsingle[authorize]: calling chap
(rlm_chap) for request 2
Mon Mar 13 12:27:17 2017 : Debug: (2) modsingle[authorize]: returned from
chap (rlm_chap) for request 2
Mon Mar 13 12:27:17 2017 : Debug: (2)   [chap] = noop
Mon Mar 13 12:27:17 2017 : Debug: (2)  modsingle[authorize]: calling mschap
(rlm_mschap) for request 2
Mon Mar 13 12:27:17 2017 : Debug: (2) modsingle[authorize]: returned from
mschap (rlm_mschap) for request 2
Mon Mar 13 12:27:17 2017 : Debug: (2)   [mschap] = noop
Mon Mar 13 12:27:17 2017 : Debug: (2)  modsingle[authorize]: calling digest
(rlm_digest) for request 2
Mon Mar 13 12:27:17 2017 : Debug: (2) modsingle[authorize]: returned from
digest (rlm_digest) for request 2
Mon Mar 13 12:27:17 2017 : Debug: (2)   [digest] = noop
Mon Mar 13 12:27:17 2017 : Debug: (2)  modsingle[authorize]: calling suffix
(rlm_realm) for request 2
Mon Mar 13 12:27:17 2017 : Debug: (2)  suffix : Checking for suffix after
"@"
Mon Mar 13 12:27:17 2017 : Debug: (2)  suffix : No '@' in User-Name =
"k00jlod", looking up realm NULL
Mon Mar 13 12:27:17 2017 : Debug: (2)  suffix : No such realm "NULL"
Mon Mar 13 12:27:17 2017 : Debug: (2) modsingle[authorize]: returned from
suffix (rlm_realm) for request 2
Mon Mar 13 12:27:17 2017 : Debug: (2)   [suffix] = noop
Mon Mar 13 12:27:17 2017 : Debug: (2)  modsingle[authorize]: calling eap
(rlm_eap) for request 2
Mon Mar 13 12:27:17 2017 : Debug: (2)  eap : No EAP-Message, not doing EAP
Mon Mar 13 12:27:17 2017 : Debug: (2) modsingle[authorize]: returned from
eap (rlm_eap) for request 2
Mon Mar 13 12:27:17 2017 : Debug: (2)   [eap] = noop
Mon Mar 13 12:27:17 2017 : Debug: (2)  modsingle[authorize]: calling files
(rlm_files) for request 2
Mon Mar 13 12:27:17 2017 : Debug: (2) modsingle[authorize]: returned from
files (rlm_files) for request 2
Mon Mar 13 12:27:17 2017 : Debug: (2)   [files] = noop
Mon Mar 13 12:27:17 2017 : Debug: (2)  modsingle[authorize]: calling
expiration (rlm_expiration) for request 2
Mon Mar 13 12:27:17 2017 : Debug: (2) modsingle[authorize]: returned from
expiration (rlm_expiration) for request 2
Mon Mar 13 12:27:17 2017 : Debug: (2)   [expiration] = noop
Mon Mar 13 12:27:17 2017 : Debug: (2)  modsingle[authorize]: calling
logintime (rlm_logintime) for request 2
Mon Mar 13 12:27:17 2017 : Debug: (2) modsingle[authorize]: returned from
logintime (rlm_logintime) for request 2
Mon Mar 13 12:27:17 2017 : Debug: (2)   [logintime] = noop
Mon Mar 13 12:27:17 2017 : Debug: (2)  modsingle[authorize]: calling pap
(rlm_pap) for request 2
Mon Mar 13 12:27:17 2017 : WARNING: (2)  pap : No "known good" password
found for the user.  Not setting Auth-Type
Mon Mar 13 12:27:17 2017 : WARNING: (2)  pap : Authentication will fail
unless a "known good" password is available
Mon Mar 13 12:27:17 2017 : Debug: (2) modsingle[authorize]: returned from
pap (rlm_pap) for request 2
Mon Mar 13 12:27:17 2017 : Debug: (2)   [pap] = noop
Mon Mar 13 12:27:17 2017 : Debug: (2)  } #  authorize = ok
Mon Mar 13 12:27:17 2017 : Debug: (2) Found Auth-Type = perl
Mon Mar 13 12:27:17 2017 : Debug: (2) # Executing group from file
/etc/raddb/sites-enabled/default
Mon Mar 13 12:27:17 2017 : Debug: (2)   authenticate {
Mon Mar 13 12:27:17 2017 : Debug: (2)  modsingle[authenticate]: calling
perl (rlm_perl) for request 2
Mon Mar 13 12:27:17 2017 : Debug: (2)   perl : $RAD_REQUEST{'User-Name'} =
&request:User-Name -> 'k00jlod'
Mon Mar 13 12:27:17 2017 : Debug: (2)   perl :
$RAD_REQUEST{'User-Password'} = &request:User-Password -> '876274'
Mon Mar 13 12:27:17 2017 : Debug: (2)   perl :
$RAD_REQUEST{'NAS-IP-Address'} = &request:NAS-IP-Address -> '172.28.0.18'
Mon Mar 13 12:27:17 2017 : Debug: (2)   perl : $RAD_REQUEST{'NAS-Port'} =
&request:NAS-Port -> '27713536'
Mon Mar 13 12:27:17 2017 : Debug: (2)   perl : $RAD_REQUEST{'State'} =
&request:State -> '0x3433393334373936'
Mon Mar 13 12:27:17 2017 : Debug: (2)   perl :
$RAD_REQUEST{'Called-Station-Id'} = &request:Called-Station-Id ->
'82.147.36.212'
Mon Mar 13 12:27:17 2017 : Debug: (2)   perl :
$RAD_REQUEST{'Calling-Station-Id'} = &request:Calling-Station-Id ->
'77.106.182.238'
Mon Mar 13 12:27:17 2017 : Debug: (2)   perl :
$RAD_REQUEST{'NAS-Port-Type'} = &request:NAS-Port-Type -> 'Virtual'
Mon Mar 13 12:27:17 2017 : Debug: (2)   perl :
$RAD_REQUEST{'Tunnel-Client-Endpoint'} = &request:Tunnel-Client-Endpoint ->
'77.106.182.238'
Mon Mar 13 12:27:17 2017 : Debug: (2)   perl :
$RAD_REQUEST{'Event-Timestamp'} = &request:Event-Timestamp -> 'Mar 13 2017
12:27:17 CET'
Mon Mar 13 12:27:17 2017 : Debug: (2)   perl : $RAD_REQUEST{'Cisco-AVPair'}
= &request:Cisco-AVPair -> 'ip:source-ip=77.106.182.238'
Mon Mar 13 12:27:17 2017 : Debug: (2)   perl :
$RAD_REQUEST{'ASA-TunnelGroupName'} = &request:ASA-TunnelGroupName ->
'Two-factor'
Mon Mar 13 12:27:17 2017 : Debug: (2)   perl :
$RAD_REQUEST{'ASA-ClientType'} = &request:ASA-ClientType ->
'AnyConnect-Client-SSL-VPN'
Mon Mar 13 12:27:17 2017 : Debug: (2)   perl : $RAD_CHECK{'Auth-Type'} =
&control:Auth-Type -> 'perl'
Mon Mar 13 12:27:17 2017 : Debug: (2)   perl : $RAD_CONFIG{'Auth-Type'} =
&control:Auth-Type -> 'perl'
Mon Mar 13 12:27:22 2017 : Debug: (2)  perl : &request:NAS-Port-Type =
$RAD_REQUEST{'NAS-Port-Type'} -> 'Virtual'
Mon Mar 13 12:27:22 2017 : Debug: (2)  perl : &request:ASA-ClientType =
$RAD_REQUEST{'ASA-ClientType'} -> 'AnyConnect-Client-SSL-VPN'
Mon Mar 13 12:27:22 2017 : Debug: (2)  perl : &request:ASA-TunnelGroupName
= $RAD_REQUEST{'ASA-TunnelGroupName'} -> 'Two-factor'
Mon Mar 13 12:27:22 2017 : Debug: (2)  perl : &request:Calling-Station-Id =
$RAD_REQUEST{'Calling-Station-Id'} -> '77.106.182.238'
Mon Mar 13 12:27:22 2017 : Debug: (2)  perl : &request:Called-Station-Id =
$RAD_REQUEST{'Called-Station-Id'} -> '82.147.36.212'
Mon Mar 13 12:27:22 2017 : Debug: (2)  perl : &request:State =
$RAD_REQUEST{'State'} -> '0x3433393334373936'
Mon Mar 13 12:27:22 2017 : Debug: (2)  perl : &request:Cisco-AVPair =
$RAD_REQUEST{'Cisco-AVPair'} -> 'ip:source-ip=77.106.182.238'
Mon Mar 13 12:27:22 2017 : Debug: (2)  perl : &request:User-Name =
$RAD_REQUEST{'User-Name'} -> 'k00jlod'
Mon Mar 13 12:27:22 2017 : Debug: (2)  perl : &request:Event-Timestamp =
$RAD_REQUEST{'Event-Timestamp'} -> 'Mar 13 2017 12:27:17 CET'
Mon Mar 13 12:27:22 2017 : Debug: (2)  perl : &request:User-Password =
$RAD_REQUEST{'User-Password'} -> '876274'
Mon Mar 13 12:27:22 2017 : Debug: (2)  perl :
&request:Tunnel-Client-Endpoint:0 =
$RAD_REQUEST{'Tunnel-Client-Endpoint:0'} -> '77.106.182.238'
Mon Mar 13 12:27:22 2017 : Debug: (2)  perl : &request:NAS-IP-Address =
$RAD_REQUEST{'NAS-IP-Address'} -> '172.28.0.18'
Mon Mar 13 12:27:22 2017 : Debug: (2)  perl : &request:NAS-Port =
$RAD_REQUEST{'NAS-Port'} -> '27713536'
Mon Mar 13 12:27:22 2017 : Debug: (2)  perl : &control:Auth-Type =
$RAD_CHECK{'Auth-Type'} -> 'perl'
Mon Mar 13 12:27:22 2017 : Debug: (2) modsingle[authenticate]: returned
from perl (rlm_perl) for request 2
Mon Mar 13 12:27:22 2017 : Debug: (2)   [perl] = ok
Mon Mar 13 12:27:22 2017 : Debug: (2)  } #  authenticate = ok
Mon Mar 13 12:27:22 2017 : Debug: (2) # Executing section post-auth from
file /etc/raddb/sites-enabled/default
Mon Mar 13 12:27:22 2017 : Debug: (2)   post-auth {
Mon Mar 13 12:27:22 2017 : Debug: (2)  modsingle[post-auth]: calling exec
(rlm_exec) for request 2
Mon Mar 13 12:27:22 2017 : Debug: (2) modsingle[post-auth]: returned from
exec (rlm_exec) for request 2
Mon Mar 13 12:27:22 2017 : Debug: (2)   [exec] = noop
Mon Mar 13 12:27:22 2017 : Debug: (2)   remove_reply_message_if_eap
remove_reply_message_if_eap {
Mon Mar 13 12:27:22 2017 : Debug: (2)     if (&reply:EAP-Message &&
&reply:Reply-Message)
Mon Mar 13 12:27:22 2017 : Debug: (2)     if (&reply:EAP-Message &&
&reply:Reply-Message)  -> FALSE
Mon Mar 13 12:27:22 2017 : Debug: (2)    else else {
Mon Mar 13 12:27:22 2017 : Debug: (2)  modsingle[post-auth]: calling noop
(rlm_always) for request 2
Mon Mar 13 12:27:22 2017 : Debug: (2) modsingle[post-auth]: returned from
noop (rlm_always) for request 2
Mon Mar 13 12:27:22 2017 : Debug: (2)     [noop] = noop
Mon Mar 13 12:27:22 2017 : Debug: (2)    } # else else = noop
Mon Mar 13 12:27:22 2017 : Debug: (2)   } # remove_reply_message_if_eap
remove_reply_message_if_eap = noop
Mon Mar 13 12:27:22 2017 : Debug: (2)  } #  post-auth = noop
Mon Mar 13 12:27:22 2017 : Debug: (2) Sending Access-Accept packet to host
172.28.0.18 port 63103, id=165, length=0
Sending Access-Accept Id 165 from 10.58.0.15:1812 to 172.28.0.18:63103
Mon Mar 13 12:27:22 2017 : Debug: (2) Finished request
Mon Mar 13 12:27:22 2017 : Debug: Waking up in 4.9 seconds.

Do you have any suggestion or answer to Cisco?

Best regards,
Lasse Odden

On Mon, Mar 6, 2017 at 2:54 PM, Alan DeKok <aland@deployingradius.com>
wrote:
...
On Mar 6, 2017, at 7:55 AM, Lasse Odden <lasse.odden@gmail.com> wrote:
...
I've set up a two-factor athentication against our Cisco AnyConnect VPN
with access-challenge (this works when I use PAP between Cisco and
FreeRADIUS).
That's a common scenario.
...
But with the username and password being sent between the Cisco and the
FreeRADIUS-server in cleartext I enabled "Password management" on the
Cisco
ASA, so it sends the password with MS-CHAPv2.
That's less common.
...
The Cisco ASA recieves the Challenge and promts for and challenge. When I
type in the correct challenge the FreeRADIUS sends an Access-Accept, but
the Cisco ASA won't allow it.
Then the Cisco is broken.
...
My question is if this is allowed by the standard or is it a bug on
Cisco's
side?
It's definitely allowed by the standard.  But probably a situation where
the Cisco people never thought about it, and never tried it.
Alan DeKok.
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/
list/users.html